Reporting script runtimes in pg_regress

classic Classic list List threaded Threaded
25 messages Options
12
Reply | Threaded
Open this post in threaded view
|

Reporting script runtimes in pg_regress

Tom Lane-2
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();
 }
 
Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Peter Geoghegan-4
On Sat, Feb 9, 2019 at 7:50 PM Tom Lane <[hidden email]> wrote:
> 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.

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

It definitely seems useful to me.

--
Peter Geoghegan

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Andres Freund
In reply to this post by Tom Lane-2
Hi,

On February 10, 2019 9:20:18 AM GMT+05:30, Tom Lane <[hidden email]> wrote:

>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?

Yes, it does. I've locally been playing with parallelizing isolationtester's schedule, and it's quite useful for coming up with a schedule that's optimized.

Andres
--
Sent from my Android device with K-9 Mail. Please excuse my brevity.

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Daniel Gustafsson
In reply to this post by Tom Lane-2
> On 10 Feb 2019, at 04:50, Tom Lane <[hidden email]> wrote:

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

Absolutely, +1 on this.  In Greenplum we print the runtime of the script and
the runtime of the diff, both of which have provided useful feedback on where
to best spend optimization efforts (the diff time of course being a lot less
interesting in upstream postgres due to gpdb having it’s own diff tool to
handle segment variability).

cheers ./daniel
Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Tom Lane-2
Daniel Gustafsson <[hidden email]> writes:
>> On 10 Feb 2019, at 04:50, Tom Lane <[hidden email]> wrote:
>> Does anyone else feel that this is interesting/useful data?

> Absolutely, +1 on this.  In Greenplum we print the runtime of the script and
> the runtime of the diff, both of which have provided useful feedback on where
> to best spend optimization efforts (the diff time of course being a lot less
> interesting in upstream postgres due to gpdb having it’s own diff tool to
> handle segment variability).

Seems like I'm far from the first to think of this --- I wonder why
nobody submitted a patch before?

Anyway, pushed.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Peter Eisentraut-6
On 10/02/2019 22:55, Tom Lane wrote:

> Daniel Gustafsson <[hidden email]> writes:
>>> On 10 Feb 2019, at 04:50, Tom Lane <[hidden email]> wrote:
>>> Does anyone else feel that this is interesting/useful data?
>
>> Absolutely, +1 on this.  In Greenplum we print the runtime of the script and
>> the runtime of the diff, both of which have provided useful feedback on where
>> to best spend optimization efforts (the diff time of course being a lot less
>> interesting in upstream postgres due to gpdb having it’s own diff tool to
>> handle segment variability).
>
> Seems like I'm far from the first to think of this --- I wonder why
> nobody submitted a patch before?

Now that I see this in action, it makes the actual test results harder
to identify flying by.  I understand the desire to collect this timing
data, but that is a special use case and not relevant to the normal use
of the test suite, which is to see whether the test passes.  Can we make
this optional please?

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Tom Lane-2
Peter Eisentraut <[hidden email]> writes:
> Now that I see this in action, it makes the actual test results harder
> to identify flying by.  I understand the desire to collect this timing
> data, but that is a special use case and not relevant to the normal use
> of the test suite, which is to see whether the test passes.  Can we make
> this optional please?

Well, I want the buildfarm to produce this info, so it's hard to see
how to get that without the timings being included by default.  I take
your point that it makes the display look a bit cluttered, though.
Would it help to put more whitespace between the status and the timing?

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Amit Langote-2
On 2019/02/11 23:30, Tom Lane wrote:

> Peter Eisentraut <[hidden email]> writes:
>> Now that I see this in action, it makes the actual test results harder
>> to identify flying by.  I understand the desire to collect this timing
>> data, but that is a special use case and not relevant to the normal use
>> of the test suite, which is to see whether the test passes.  Can we make
>> this optional please?
>
> Well, I want the buildfarm to produce this info, so it's hard to see
> how to get that without the timings being included by default.  I take
> your point that it makes the display look a bit cluttered, though.
> Would it help to put more whitespace between the status and the timing?

+1.  Maybe, not as much whitespace as we get today between the test name
and "... ok", but at least more than just a single space.

Thanks,
Amit


Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Michael Paquier-2
On Tue, Feb 12, 2019 at 10:29:40AM +0900, Amit Langote wrote:

> On 2019/02/11 23:30, Tom Lane wrote:
>> Peter Eisentraut <[hidden email]> writes:
>>> Now that I see this in action, it makes the actual test results harder
>>> to identify flying by.  I understand the desire to collect this timing
>>> data, but that is a special use case and not relevant to the normal use
>>> of the test suite, which is to see whether the test passes.  Can we make
>>> this optional please?
>>
>> Well, I want the buildfarm to produce this info, so it's hard to see
>> how to get that without the timings being included by default.  I take
>> your point that it makes the display look a bit cluttered, though.
>> Would it help to put more whitespace between the status and the timing?
>
> +1.  Maybe, not as much whitespace as we get today between the test name
> and "... ok", but at least more than just a single space.
Sure, but do we need feedback immediately?  I am just catching up on
that, and I too find a bit annoying that this is not controlled by a
switch which is disabled by default.  It seems to me that this points
out to another issue that there is no actual way to pass down custom
options to pg_regress other than PG_REGRESS_DIFF_OPTS to control the
diff output format.  So we may also want something like
PG_REGRESS_OPTS.
--
Michael

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Peter Eisentraut-6
In reply to this post by Tom Lane-2
On 2019-02-11 15:30, Tom Lane wrote:

> Peter Eisentraut <[hidden email]> writes:
>> Now that I see this in action, it makes the actual test results harder
>> to identify flying by.  I understand the desire to collect this timing
>> data, but that is a special use case and not relevant to the normal use
>> of the test suite, which is to see whether the test passes.  Can we make
>> this optional please?
>
> Well, I want the buildfarm to produce this info, so it's hard to see
> how to get that without the timings being included by default.  I take
> your point that it makes the display look a bit cluttered, though.

Can we enable it through the buildfarm client?

Or we could write it into a separate log file.

> Would it help to put more whitespace between the status and the timing?

prove --timer produces this:

[14:21:32] t/001_basic.pl ............ ok     9154 ms ( 0.00 usr  0.01 sys +  2.28 cusr  3.40 csys =  5.69 CPU)
[14:21:41] t/002_databases.pl ........ ok    11294 ms ( 0.00 usr  0.00 sys +  2.16 cusr  3.84 csys =  6.00 CPU)
[14:21:52] t/003_extrafiles.pl ....... ok     7736 ms ( 0.00 usr  0.00 sys +  1.89 cusr  2.91 csys =  4.80 CPU)
[14:22:00] t/004_pg_xlog_symlink.pl .. ok     9035 ms ( 0.00 usr  0.00 sys +  2.03 cusr  3.02 csys =  5.05 CPU)
[14:22:09] t/005_same_timeline.pl .... ok     8048 ms ( 0.00 usr  0.00 sys +  0.92 cusr  1.29 csys =  2.21 CPU)

which seems quite readable.  So maybe something like this:

     identity                     ... ok      238 ms
     partition_join               ... ok      429 ms
     partition_prune              ... ok      786 ms
     reloptions                   ... ok       94 ms
     hash_part                    ... ok       78 ms
     indexing                     ... ok     1298 ms
     partition_aggregate          ... ok      727 ms
     partition_info               ... ok      110 ms
test event_trigger                ... ok      128 ms
test fast_default                 ... ok      173 ms
test stats                        ... ok      637 ms

which would be

-           status(_(" (%.0f ms)"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+           status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));

(times two).

If we're going to keep this, should we enable the prove --timer option as well?

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Peter Eisentraut-6
On 2019-02-15 14:32, Peter Eisentraut wrote:

>      identity                     ... ok      238 ms
>      partition_join               ... ok      429 ms
>      partition_prune              ... ok      786 ms
>      reloptions                   ... ok       94 ms
>      hash_part                    ... ok       78 ms
>      indexing                     ... ok     1298 ms
>      partition_aggregate          ... ok      727 ms
>      partition_info               ... ok      110 ms
> test event_trigger                ... ok      128 ms
> test fast_default                 ... ok      173 ms
> test stats                        ... ok      637 ms

We should also strive to align "FAILED" properly.  This is currently
quite unreadable:

     int4                         ... ok (128 ms)
     int8                         ... FAILED (153 ms)
     oid                          ... ok (163 ms)
     float4                       ... ok (231 ms)

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Tom Lane-2
Peter Eisentraut <[hidden email]> writes:
> On 2019-02-15 14:32, Peter Eisentraut wrote:
>> test event_trigger                ... ok      128 ms
>> test fast_default                 ... ok      173 ms
>> test stats                        ... ok      637 ms

That looks reasonable, although on machines where test runtimes run
into the tens of seconds, there's not going to be nearly as much
whitespace as this example suggests.

> We should also strive to align "FAILED" properly.

Hmm.  The reasonable ways to accomplish that look to be either
(a) pad "ok" to the width of "FAILED", or (b) rely on emitting a tab.
I don't much like either, especially from the localization angle.
One should also note that FAILED often comes along with additional
verbiage, such as "(ignored)" or a note about process exit status;
so I think making such cases line up totally neatly is a lost cause
anyway.

How do you feel about letting it do this:

      int4                         ... ok      128 ms
      int8                         ... FAILED      153 ms
      oid                          ... ok      163 ms
      float4                       ... ok      231 ms

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

John Naylor-2
In reply to this post by Peter Eisentraut-6
On 2/15/19, Peter Eisentraut <[hidden email]> wrote:
> We should also strive to align "FAILED" properly.  This is currently
> quite unreadable:
>
>      int4                         ... ok (128 ms)
>      int8                         ... FAILED (153 ms)
>      oid                          ... ok (163 ms)
>      float4                       ... ok (231 ms)

If I may play devil's advocate, who cares how long it takes a test to
fail? If it's not difficult, leaving the time out for failures would
make them stand out more.

--
John Naylor                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Tom Lane-2
In reply to this post by Peter Eisentraut-6
Peter Eisentraut <[hidden email]> writes:
> If we're going to keep this, should we enable the prove --timer option as well?

As far as that goes: I've found that in some of my older Perl
installations, prove doesn't recognize the --timer switch.
So turning that on would require a configuration probe of some
sort, which seems like more trouble than it's worth.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Tom Lane-2
In reply to this post by John Naylor-2
John Naylor <[hidden email]> writes:
> On 2/15/19, Peter Eisentraut <[hidden email]> wrote:
>> We should also strive to align "FAILED" properly.  This is currently
>> quite unreadable:
>>
>> int4                         ... ok (128 ms)
>> int8                         ... FAILED (153 ms)
>> oid                          ... ok (163 ms)
>> float4                       ... ok (231 ms)

> If I may play devil's advocate, who cares how long it takes a test to
> fail? If it's not difficult, leaving the time out for failures would
> make them stand out more.

Actually, I'd supposed that that might be useful info, sometimes.
For example it might help you guess whether a timeout had elapsed.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Peter Eisentraut-6
In reply to this post by Tom Lane-2
On 2019-02-15 15:54, Tom Lane wrote:
>> We should also strive to align "FAILED" properly.
> Hmm.  The reasonable ways to accomplish that look to be either
> (a) pad "ok" to the width of "FAILED", or (b) rely on emitting a tab.
> I don't much like either, especially from the localization angle.
> One should also note that FAILED often comes along with additional
> verbiage, such as "(ignored)" or a note about process exit status;
> so I think making such cases line up totally neatly is a lost cause
> anyway.

Yeah, not strictly required, but someone might want to play around with
it a bit.

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Alvaro Herrera-9
On 2019-Feb-18, Peter Eisentraut wrote:

> On 2019-02-15 15:54, Tom Lane wrote:
> >> We should also strive to align "FAILED" properly.
> > Hmm.  The reasonable ways to accomplish that look to be either
> > (a) pad "ok" to the width of "FAILED", or (b) rely on emitting a tab.
> > I don't much like either, especially from the localization angle.
> > One should also note that FAILED often comes along with additional
> > verbiage, such as "(ignored)" or a note about process exit status;
> > so I think making such cases line up totally neatly is a lost cause
> > anyway.
>
> Yeah, not strictly required, but someone might want to play around with
> it a bit.

FWIW I don't think we localize pg_regress output currently, so that
argument seems moot ... But I think we can get away with constant four
spaces for now.

If we wanted to get really fancy, for interactive use we could colorize
the output.  (I wonder if there's a way to get browsers to colorize
text/plain output somehow instead of printing the ansi codes).

--
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Tom Lane-2
Alvaro Herrera <[hidden email]> writes:
> On 2019-Feb-18, Peter Eisentraut wrote:
>>> We should also strive to align "FAILED" properly.

>> Yeah, not strictly required, but someone might want to play around with
>> it a bit.

> FWIW I don't think we localize pg_regress output currently, so that
> argument seems moot ... But I think we can get away with constant four
> spaces for now.

I pushed Peter's suggestion for %8.0f; let's live with that for a little
and see if it's still annoying.

                        regards, tom lane

Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Christoph Berg-2
Re: Tom Lane 2019-02-18 <[hidden email]>

> >>> We should also strive to align "FAILED" properly.
>
> >> Yeah, not strictly required, but someone might want to play around with
> >> it a bit.
>
> > FWIW I don't think we localize pg_regress output currently, so that
> > argument seems moot ... But I think we can get away with constant four
> > spaces for now.
>
> I pushed Peter's suggestion for %8.0f; let's live with that for a little
> and see if it's still annoying.
The ryu changes make postgresql-unit fail quite loudly:

$ cat regression.out
test extension                    ... ok      359 ms
test tables                       ... FAILED      164 ms
test unit                         ... FAILED      867 ms
test binary                       ... ok       20 ms
test unicode                      ... ok       18 ms
test prefix                       ... FAILED       43 ms
test units                        ... FAILED      207 ms
test time                         ... FAILED       99 ms
test temperature                  ... FAILED       22 ms
...

The misalignment annoyed me enough (especially the false alignment
between "ms" on the first row and "164" on the next row) to look into
it. Aligned it looks like this:

test extension                    ... ok          399 ms
test tables                       ... FAILED      190 ms
test unit                         ... FAILED      569 ms
test binary                       ... ok           14 ms
test unicode                      ... ok           15 ms
test prefix                       ... FAILED       44 ms
test units                        ... FAILED      208 ms
test time                         ... FAILED       99 ms
test temperature                  ... FAILED       21 ms
...

It doesn't break translations because it prints the extra spaces
separately.

In run_single_test() (which this output is from), it simply aligns the
output with FAILED. In run_schedule(), there is the 3rd output string
"failed (ignored)" which is considerably longer. I aligned the output
with that, but also made the timestamp field shorter so it's not too
much to the right.

Christoph

0001-Align-timestamps-in-pg_regress-output.patch (1K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Reporting script runtimes in pg_regress

Peter Eisentraut-6
On 2019-02-21 10:37, Christoph Berg wrote:

> diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
> index a18a6f6c45..8080626e94 100644
> --- a/src/test/regress/pg_regress.c
> +++ b/src/test/regress/pg_regress.c
> @@ -1794,12 +1794,14 @@ run_schedule(const char *schedule, test_function tfunc)
>   else
>   {
>   status(_("FAILED"));
> + status("          "); /* align with failed (ignored) */
>   fail_count++;
>   }

So an issue here is that in theory "FAILED" etc. are marked for
translation but your spacers do not take that into account.  Personally,
I have no ambition to translate pg_regress, so we could remove all that.
 But it should be done consistently in either case.

I also think we shouldn't worry about the "failed (ignored)" case.  That
never happens, and I don't want to mess up the spacing we have now for
that.  I'd consider removing support for it altogether.

--
Peter Eisentraut              http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

12