From: Tom Lane <tgl@sss.pgh.pa.us>
To: pgsql-hackers@lists.postgresql.org
Subject: Reporting script runtimes in pg_regress
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <16592.1549770551.0@sss.pgh.pa.us>
Date: Sat, 09 Feb 2019 22:50:18 -0500
Message-ID: <16646.1549770618@sss.pgh.pa.us>
Precedence: bulk

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <16592.1549770551.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable

I've wondered for some time whether we couldn't make a useful
reduction in the run time of the PG regression tests by looking
for scripts that run significantly longer than others in their
parallel groups, and making an effort to trim the runtimes of
those particular scripts.

The first step in that of course is to get some data, so attached
is a patch to pg_regress to cause it to print the runtime of each
script.  This produces results like, say,

parallel group (17 tests):  circle line timetz path lseg point macaddr mac=
addr8 time interval inet tstypes date box timestamp timestamptz polygon
     point                        ... ok (35 ms)
     lseg                         ... ok (31 ms)
     line                         ... ok (23 ms)
     box                          ... ok (135 ms)
     path                         ... ok (24 ms)
     polygon                      ... ok (1256 ms)
     circle                       ... ok (20 ms)
     date                         ... ok (69 ms)
     time                         ... ok (40 ms)
     timetz                       ... ok (22 ms)
     timestamp                    ... ok (378 ms)
     timestamptz                  ... ok (378 ms)
     interval                     ... ok (50 ms)
     inet                         ... ok (56 ms)
     macaddr                      ... ok (33 ms)
     macaddr8                     ... ok (37 ms)
     tstypes                      ... ok (62 ms)

or on a rather slower machine,

parallel group (8 tests):  hash_part reloptions partition_info identity pa=
rtition_join partition_aggregate partition_prune indexing
     identity                     ... ok (3807 ms)
     partition_join               ... ok (10433 ms)
     partition_prune              ... ok (19370 ms)
     reloptions                   ... ok (1166 ms)
     hash_part                    ... ok (628 ms)
     indexing                     ... ok (22070 ms)
     partition_aggregate          ... ok (12731 ms)
     partition_info               ... ok (1373 ms)
test event_trigger                ... ok (1953 ms)
test fast_default                 ... ok (2689 ms)
test stats                        ... ok (1173 ms)

Does anyone else feel that this is interesting/useful data?

			regards, tom lane


------- =_aaaaaaaaaa0
Content-Type: text/x-diff; name="print-test-script-runtimes-1.patch";
	charset="us-ascii"
Content-ID: <16592.1549770551.2@sss.pgh.pa.us>
Content-Description: print-test-script-runtimes-1.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index 4b742a1..a4caa22 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -36,6 +36,7 @@
 #include "getopt_long.h"
 #include "libpq/pqcomm.h"		/* needed for UNIXSOCK_PATH() */
 #include "pg_config_paths.h"
+#include "portability/instr_time.h"
 =

 /* for resultmap we need a list of pairs of strings */
 typedef struct _resultmap
@@ -1473,14 +1474,15 @@ results_differ(const char *testname, const char *r=
esultsfile, const char *defaul
 =

 /*
  * Wait for specified subprocesses to finish, and return their exit
- * statuses into statuses[]
+ * statuses into statuses[] and stop times into stoptimes[]
  *
  * If names isn't NULL, print each subprocess's name as it finishes
  *
  * Note: it's OK to scribble on the pids array, but not on the names arra=
y
  */
 static void
-wait_for_tests(PID_TYPE * pids, int *statuses, char **names, int num_test=
s)
+wait_for_tests(PID_TYPE * pids, int *statuses, instr_time *stoptimes,
+			   char **names, int num_tests)
 {
 	int			tests_left;
 	int			i;
@@ -1533,6 +1535,7 @@ wait_for_tests(PID_TYPE * pids, int *statuses, char =
**names, int num_tests)
 #endif
 				pids[i] =3D INVALID_PID;
 				statuses[i] =3D (int) exit_status;
+				INSTR_TIME_SET_CURRENT(stoptimes[i]);
 				if (names)
 					status(" %s", names[i]);
 				tests_left--;
@@ -1582,6 +1585,8 @@ run_schedule(const char *schedule, test_function tfu=
nc)
 	_stringlist *expectfiles[MAX_PARALLEL_TESTS];
 	_stringlist *tags[MAX_PARALLEL_TESTS];
 	PID_TYPE	pids[MAX_PARALLEL_TESTS];
+	instr_time	starttimes[MAX_PARALLEL_TESTS];
+	instr_time	stoptimes[MAX_PARALLEL_TESTS];
 	int			statuses[MAX_PARALLEL_TESTS];
 	_stringlist *ignorelist =3D NULL;
 	char		scbuf[1024];
@@ -1687,7 +1692,8 @@ run_schedule(const char *schedule, test_function tfu=
nc)
 		{
 			status(_("test %-28s ... "), tests[0]);
 			pids[0] =3D (tfunc) (tests[0], &resultfiles[0], &expectfiles[0], &tags=
[0]);
-			wait_for_tests(pids, statuses, NULL, 1);
+			INSTR_TIME_SET_CURRENT(starttimes[0]);
+			wait_for_tests(pids, statuses, stoptimes, NULL, 1);
 			/* status line is finished below */
 		}
 		else if (max_concurrent_tests > 0 && max_concurrent_tests < num_tests)
@@ -1707,12 +1713,15 @@ run_schedule(const char *schedule, test_function t=
func)
 				if (i - oldest >=3D max_connections)
 				{
 					wait_for_tests(pids + oldest, statuses + oldest,
+								   stoptimes + oldest,
 								   tests + oldest, i - oldest);
 					oldest =3D i;
 				}
 				pids[i] =3D (tfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tag=
s[i]);
+				INSTR_TIME_SET_CURRENT(starttimes[i]);
 			}
 			wait_for_tests(pids + oldest, statuses + oldest,
+						   stoptimes + oldest,
 						   tests + oldest, i - oldest);
 			status_end();
 		}
@@ -1722,8 +1731,9 @@ run_schedule(const char *schedule, test_function tfu=
nc)
 			for (i =3D 0; i < num_tests; i++)
 			{
 				pids[i] =3D (tfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tag=
s[i]);
+				INSTR_TIME_SET_CURRENT(starttimes[i]);
 			}
-			wait_for_tests(pids, statuses, tests, num_tests);
+			wait_for_tests(pids, statuses, stoptimes, tests, num_tests);
 			status_end();
 		}
 =

@@ -1793,6 +1803,9 @@ run_schedule(const char *schedule, test_function tfu=
nc)
 			if (statuses[i] !=3D 0)
 				log_child_failure(statuses[i]);
 =

+			INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
+			status(_(" (%.0f ms)"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+
 			status_end();
 		}
 =

@@ -1818,6 +1831,8 @@ static void
 run_single_test(const char *test, test_function tfunc)
 {
 	PID_TYPE	pid;
+	instr_time	starttime;
+	instr_time	stoptime;
 	int			exit_status;
 	_stringlist *resultfiles =3D NULL;
 	_stringlist *expectfiles =3D NULL;
@@ -1829,7 +1844,8 @@ run_single_test(const char *test, test_function tfun=
c)
 =

 	status(_("test %-28s ... "), test);
 	pid =3D (tfunc) (test, &resultfiles, &expectfiles, &tags);
-	wait_for_tests(&pid, &exit_status, NULL, 1);
+	INSTR_TIME_SET_CURRENT(starttime);
+	wait_for_tests(&pid, &exit_status, &stoptime, NULL, 1);
 =

 	/*
 	 * Advance over all three lists simultaneously.
@@ -1867,6 +1883,9 @@ run_single_test(const char *test, test_function tfun=
c)
 	if (exit_status !=3D 0)
 		log_child_failure(exit_status);
 =

+	INSTR_TIME_SUBTRACT(stoptime, starttime);
+	status(_(" (%.0f ms)"), INSTR_TIME_GET_MILLISEC(stoptime));
+
 	status_end();
 }
 =


------- =_aaaaaaaaaa0--