Re: Reporting script runtimes in pg_regress
On 2019-03-21 12:51, Christoph Berg wrote:
> Re: David Steele 2019-03-20
> <8a85bece-b18f-0433-acf3-d106b31f0...@pgmasters.net>
Oh, right. So the way to go would be to use _("FAILED "), and
ask translators to use the same length.
>>>
>>> Note there's no translation for pg_regress. All these _() markers are
>>> currently dead code. It seems hard to become motivated to translate
>>> that kind of program. I don't think it has much value, myself.
>>
>> This patch has been "Waiting on Author" since March 8th. Do you know when
>> you'll have a new version ready?
>
> Here is a new revision that blank-pads "ok" to the length of "FAILED".
committed
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Re: Reporting script runtimes in pg_regress
Re: David Steele 2019-03-20 <8a85bece-b18f-0433-acf3-d106b31f0...@pgmasters.net>
> > > Oh, right. So the way to go would be to use _("FAILED "), and
> > > ask translators to use the same length.
> >
> > Note there's no translation for pg_regress. All these _() markers are
> > currently dead code. It seems hard to become motivated to translate
> > that kind of program. I don't think it has much value, myself.
>
> This patch has been "Waiting on Author" since March 8th. Do you know when
> you'll have a new version ready?
Here is a new revision that blank-pads "ok" to the length of "FAILED".
Christoph
>From cd2a5927b52473ca9c56e2e5142c257853429224 Mon Sep 17 00:00:00 2001
From: Christoph Berg
Date: Thu, 21 Feb 2019 10:35:19 +0100
Subject: [PATCH] Align timestamps in pg_regress output
---
src/test/regress/pg_regress.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c
index a18a6f6c45..8111d95b1e 100644
--- a/src/test/regress/pg_regress.c
+++ b/src/test/regress/pg_regress.c
@@ -1799,7 +1799,7 @@ run_schedule(const char *schedule, test_function tfunc)
}
else
{
-status(_("ok"));
+status(_("ok")); /* align with FAILED */
success_count++;
}
@@ -1879,7 +1879,7 @@ run_single_test(const char *test, test_function tfunc)
}
else
{
- status(_("ok"));
+ status(_("ok")); /* align with FAILED */
success_count++;
}
--
2.20.1
Re: Re: Reporting script runtimes in pg_regress
Hi Christophe,
On 3/8/19 5:12 PM, Alvaro Herrera wrote:
On 2019-Mar-08, Christoph Berg wrote:
Re: Peter Eisentraut 2019-03-08
<3eb194cf-b878-1f63-8623-6d6add0ed...@2ndquadrant.com>
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.
Oh, right. So the way to go would be to use _("FAILED "), and
ask translators to use the same length.
Note there's no translation for pg_regress. All these _() markers are
currently dead code. It seems hard to become motivated to translate
that kind of program. I don't think it has much value, myself.
This patch has been "Waiting on Author" since March 8th. Do you know
when you'll have a new version ready?
Regards,
--
-David
da...@pgmasters.net
Re: Reporting script runtimes in pg_regress
On 2019-Mar-08, Christoph Berg wrote:
> Re: Peter Eisentraut 2019-03-08
> <3eb194cf-b878-1f63-8623-6d6add0ed...@2ndquadrant.com>
> > 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.
>
> Oh, right. So the way to go would be to use _("FAILED "), and
> ask translators to use the same length.
Note there's no translation for pg_regress. All these _() markers are
currently dead code. It seems hard to become motivated to translate
that kind of program. I don't think it has much value, myself.
--
Álvaro Herrerahttps://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Reporting script runtimes in pg_regress
Re: Peter Eisentraut 2019-03-08
<3eb194cf-b878-1f63-8623-6d6add0ed...@2ndquadrant.com>
> 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.
Oh, right. So the way to go would be to use _("FAILED "), and
ask translators to use the same length.
> 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.
You mean removing that case from pg_regress, or removing the alignment
"support"?
Christoph
Re: Reporting script runtimes in pg_regress
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
Re: Reporting script runtimes in pg_regress
Re: Tom Lane 2019-02-18 <28360.1550506...@sss.pgh.pa.us>
> >>> 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
>From 3acba7cc50f4711abedfb61cd06b1f8e640caac5 Mon Sep 17 00:00:00 2001
From: Christoph Berg
Date: Thu, 21 Feb 2019 10:35:19 +0100
Subject: [PATCH] Align timestamps in pg_regress output
---
src/test/regress/pg_regress.c | 5 -
1 file changed, 4 insertions(+), 1 deletion(-)
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++;
}
}
else
{
status(_("ok"));
+status(" "); /* align with failed (ignored) */
success_count++;
}
@@ -1807,7 +1809,7 @@ run_schedule(const char *schedule, test_function tfunc)
log_child_failure(statuses[i]);
INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
- status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+ status(_(" %5.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
status_end();
}
@@ -1880,6 +1882,7 @@ run_single_test(const char *test, test_function tfunc)
else
{
status(_("ok"));
+ status(""); /* align with FAILED */
success_count++;
}
--
2.20.1
Re: Reporting script runtimes in pg_regress
Alvaro Herrera 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
Re: Reporting script runtimes in pg_regress
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 Herrerahttps://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Reporting script runtimes in pg_regress
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
Re: Reporting script runtimes in pg_regress
John Naylor writes: > On 2/15/19, Peter Eisentraut 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
Re: Reporting script runtimes in pg_regress
Peter Eisentraut 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
Re: Reporting script runtimes in pg_regress
On 2/15/19, Peter Eisentraut 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 Naylorhttps://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Re: Reporting script runtimes in pg_regress
Peter Eisentraut 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
Re: Reporting script runtimes in pg_regress
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
Re: Reporting script runtimes in pg_regress
On 2019-02-11 15:30, Tom Lane wrote:
> Peter Eisentraut 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 ok11294 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
Re: Reporting script runtimes in pg_regress
On Tue, Feb 12, 2019 at 10:29:40AM +0900, Amit Langote wrote: > On 2019/02/11 23:30, Tom Lane wrote: >> Peter Eisentraut 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 Description: PGP signature
Re: Reporting script runtimes in pg_regress
On 2019/02/11 23:30, Tom Lane wrote: > Peter Eisentraut 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
Re: Reporting script runtimes in pg_regress
Peter Eisentraut 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
Re: Reporting script runtimes in pg_regress
On 10/02/2019 22:55, Tom Lane wrote: > Daniel Gustafsson writes: >>> On 10 Feb 2019, at 04:50, Tom Lane 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
Re: Reporting script runtimes in pg_regress
Daniel Gustafsson writes: >> On 10 Feb 2019, at 04:50, Tom Lane 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
Re: Reporting script runtimes in pg_regress
> On 10 Feb 2019, at 04:50, Tom Lane 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
Re: Reporting script runtimes in pg_regress
Hi, On February 10, 2019 9:20:18 AM GMT+05:30, Tom Lane 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.
Re: Reporting script runtimes in pg_regress
On Sat, Feb 9, 2019 at 7:50 PM Tom Lane 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
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 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], [0], [0], [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], [i], [i], [i]);
+INSTR_TIME_SET_CURRENT(starttimes[i]);
}
wait_for_tests(pids + oldest, statuses + oldest,
+ stoptimes + oldest,
tests + oldest, i - oldest);
status_end();
}
