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 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
partition_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
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();
}
