Reporting script runtimes in pg_regress

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 macaddr8 time interval inet tstypes date box
timestamptimestamptz 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 partition_join partition_aggregate
partition_pruneindexing 
     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

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 *resultsfile, 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 array
  */
 static void
-wait_for_tests(PID_TYPE * pids, int *statuses, char **names, int num_tests)
+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] = INVALID_PID;
                 statuses[i] = (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 tfunc)
     _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 = NULL;
     char        scbuf[1024];
@@ -1687,7 +1692,8 @@ run_schedule(const char *schedule, test_function tfunc)
         {
             status(_("test %-28s ... "), tests[0]);
             pids[0] = (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 tfunc)
                 if (i - oldest >= max_connections)
                 {
                     wait_for_tests(pids + oldest, statuses + oldest,
+                                   stoptimes + oldest,
                                    tests + oldest, i - oldest);
                     oldest = i;
                 }
                 pids[i] = (tfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[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 tfunc)
             for (i = 0; i < num_tests; i++)
             {
                 pids[i] = (tfunc) (tests[i], &resultfiles[i], &expectfiles[i], &tags[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 tfunc)
             if (statuses[i] != 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 = NULL;
     _stringlist *expectfiles = NULL;
@@ -1829,7 +1844,8 @@ run_single_test(const char *test, test_function tfunc)

     status(_("test %-28s ... "), test);
     pid = (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 tfunc)
     if (exit_status != 0)
         log_child_failure(exit_status);

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