TAP output format in pg_regress

On 22 Feb 2022, at 00:08, Daniel Gustafsson <daniel@yesql.se> wrote:

I'll fix that.

The attached v3 fixes that thinko, and cleans up a lot of the output which
isn't diagnostic per the TAP spec to make it less noisy. It also fixes tag
support used in the ECPG tests and a few small cleanups. There is a blank line
printed which needs to be fixed, but I'm running out of time and wanted to get
a non-broken version on the list before putting it aside for today.

The errorpaths that exit(2) the testrun should be converted to "bail out" lines
when running with TAP output, but apart from that I think it's fairly spec
compliant.

--
Daniel Gustafsson https://vmware.com/

Hi,

Thanks for the updated version!

On 2022-02-22 15:10:11 +0100, Daniel Gustafsson wrote:

The errorpaths that exit(2) the testrun should be converted to "bail out" lines
when running with TAP output, but apart from that I think it's fairly spec
compliant.

I'd much rather not use BAIL - I haven't gotten around to doing anything about
it, but I really want to get rid of nearly all our uses of bail:

/messages/by-id/20220213232249.7sevhlioapydla37@alap3.anarazel.de

Greetings,

Andres Freund

On 22 Feb 2022, at 18:13, Andres Freund <andres@anarazel.de> wrote:
On 2022-02-22 15:10:11 +0100, Daniel Gustafsson wrote:

The errorpaths that exit(2) the testrun should be converted to "bail out" lines
when running with TAP output, but apart from that I think it's fairly spec
compliant.

I'd much rather not use BAIL - I haven't gotten around to doing anything about
it, but I really want to get rid of nearly all our uses of bail:

Point. We already error out on stderr in pg_regress so we could probably make
die() equivalent output to keep the TAP parsing consistent. At any rate,
awaiting the conclusions on the bail thread and simply (for some value of)
replicating that in this patch is probably the best option?

--
Daniel Gustafsson https://vmware.com/

Hi,

On 2022-02-22 15:10:11 +0100, Daniel Gustafsson wrote:

On 22 Feb 2022, at 00:08, Daniel Gustafsson <daniel@yesql.se> wrote:

I'll fix that.

The attached v3 fixes that thinko, and cleans up a lot of the output which
isn't diagnostic per the TAP spec to make it less noisy. It also fixes tag
support used in the ECPG tests and a few small cleanups. There is a blank line
printed which needs to be fixed, but I'm running out of time and wanted to get
a non-broken version on the list before putting it aside for today.

The errorpaths that exit(2) the testrun should be converted to "bail out" lines
when running with TAP output, but apart from that I think it's fairly spec
compliant.

This is failing with segmentation faults on cfbot:
https://cirrus-ci.com/task/4879227009892352?logs=test_world#L21

Looks like something around isolationtester is broken?

Unfortunately there's no useful backtraces for isolationtester. Not sure
what's up there.

Seems like we might not have energy to push this forward in the next two
weeks, so maybe the CF entry should be marked returned or moved for now?

Greetings,

Andres Freund

On 22 Mar 2022, at 00:49, Andres Freund <andres@anarazel.de> wrote:

This is failing with segmentation faults on cfbot:
https://cirrus-ci.com/task/4879227009892352?logs=test_world#L21

Looks like something around isolationtester is broken?

It could be triggered by plpgsql tests as well, and was (as usual) a silly
mistake easily fixed when found. The attached survices repeated check-world
for me.

Seems like we might not have energy to push this forward in the next two
weeks, so maybe the CF entry should be marked returned or moved for now?

Since there is little use for this without the Meson branch, it should target
the same version as that patch. I'll move the patch to the next CF for now.

As we discussed off-list I extended this patchset with an attempt to minimize
noise as per 20220221164736.rq3ornzjdkmwk2wo@alap3.anarazel.de, but it's not
yet done. The attached has a rough draft of adding a --verbose option which
gives the current output (and potentially more for debugging), but which by
default is off producing minimal noise.

--
Daniel Gustafsson https://vmware.com/

Attached is a new version of this patch, which completes the TAP output format
option such that all codepaths emitting output are TAP compliant. The verbose
option is fixed to to not output extraneous newlines which the previous PoC
did. The output it made to conform to the original TAP spec since v13/14 TAP
parsers seem less common than those that can handle the original spec. Support
for the new format additions should be quite simple to add should we want that.

Running pg_regress --verbose should give the current format output.

I did end up combining TAP and --verbose into a single patch, as the TAP format
sort of depends on the verbose flag as TAP has no verbose mode. I can split it
into two separate should a reviewer prefer that.

--
Daniel Gustafsson https://vmware.com/

On 29.06.22 21:50, Daniel Gustafsson wrote:

Attached is a new version of this patch, which completes the TAP output format
option such that all codepaths emitting output are TAP compliant. The verbose
option is fixed to to not output extraneous newlines which the previous PoC
did. The output it made to conform to the original TAP spec since v13/14 TAP
parsers seem less common than those that can handle the original spec. Support
for the new format additions should be quite simple to add should we want that.

Running pg_regress --verbose should give the current format output.

I did end up combining TAP and --verbose into a single patch, as the TAP format
sort of depends on the verbose flag as TAP has no verbose mode. I can split it
into two separate should a reviewer prefer that.

I'm not sure what to make of all these options. I think providing a TAP
output for pg_regress is a good idea. But then do we still need the old
output? Is it worth maintaining two output formats that display exactly
the same thing in slightly different ways?

What is the purpose of the --verbose option? When and how is one
supposed to activate that? The proposed default format now hides the
fact that some tests are started in parallel. I remember the last time
I wanted to tweak the output of the parallel tests, people were very
attached to the particular timing and spacing of the current output. So
I'm not sure people will like this.

The timing output is very popular. Where is that in the TAP output?

More generally, what do you envision we do with this feature? Who is it
for, what are the tradeoffs, etc.?

Peter Eisentraut <peter.eisentraut@enterprisedb.com> writes:

I'm not sure what to make of all these options. I think providing a TAP
output for pg_regress is a good idea. But then do we still need the old
output? Is it worth maintaining two output formats that display exactly
the same thing in slightly different ways?

Probably is, because this is bad:

... The proposed default format now hides the
fact that some tests are started in parallel. I remember the last time
I wanted to tweak the output of the parallel tests, people were very
attached to the particular timing and spacing of the current output. So
I'm not sure people will like this.

and so is this:

The timing output is very popular. Where is that in the TAP output?

Both of those things are fairly critical for test development. You
need to know what else might be running in parallel with a test case,
and you need to know whether you just bloated the runtime unreasonably.

More generally, I'm unhappy about the proposal that TAP should become
the default output. There is nothing particularly human-friendly
about it, whereas the existing format is something we have tuned to
our liking over literally decades. I don't mind if there's a way to
get TAP when you're actually intending to feed it into a TAP-parsing
tool, but I am not a TAP-parsing tool and I don't see why I should
have to put up with it.

regards, tom lane

On 04.07.22 16:39, Tom Lane wrote:

Probably is, because this is bad:

... The proposed default format now hides the
fact that some tests are started in parallel. I remember the last time
I wanted to tweak the output of the parallel tests, people were very
attached to the particular timing and spacing of the current output. So
I'm not sure people will like this.

and so is this:

The timing output is very popular. Where is that in the TAP output?

Both of those things are fairly critical for test development. You
need to know what else might be running in parallel with a test case,
and you need to know whether you just bloated the runtime unreasonably.

I don't think there is a reason these couldn't be shown in TAP output as
well.

Even if we keep the two output formats in parallel, it would be good if
they showed the same set of information.

Hi,

Peter Eisentraut <peter.eisentraut@enterprisedb.com> writes:

I'm not sure what to make of all these options. I think providing a TAP
output for pg_regress is a good idea. But then do we still need the old
output? Is it worth maintaining two output formats that display exactly
the same thing in slightly different ways?

Probably is, because this is bad:

... The proposed default format now hides the
fact that some tests are started in parallel. I remember the last time
I wanted to tweak the output of the parallel tests, people were very
attached to the particular timing and spacing of the current output. So
I'm not sure people will like this.

and so is this:

The timing output is very popular. Where is that in the TAP output?

Both of those things are fairly critical for test development. You
need to know what else might be running in parallel with a test case,
and you need to know whether you just bloated the runtime unreasonably.

That should be doable with tap as well - afaics the output of that could
nearly be the same as now, preceded by a #.

The test timing output could (and I think should) also be output - but if I
read the tap specification correctly, we'd either need to make it part of the
test "description" or on a separate line.

On 2022-07-04 10:39:37 -0400, Tom Lane wrote:

More generally, I'm unhappy about the proposal that TAP should become
the default output. There is nothing particularly human-friendly
about it, whereas the existing format is something we have tuned to
our liking over literally decades. I don't mind if there's a way to
get TAP when you're actually intending to feed it into a TAP-parsing
tool, but I am not a TAP-parsing tool and I don't see why I should
have to put up with it.

I'm mostly interested in the tap format because meson's testrunner can parse
it - unsurprisingly it doesn't understand the current regress output. It's a
lot nicer to immediately be pointed to the failed test(s) than having to scan
through the output "manually".

Greetings,

Andres Freund

Hi,

On 2022-06-29 21:50:45 +0200, Daniel Gustafsson wrote:

@@ -279,8 +648,7 @@ stop_postmaster(void)
r = system(buf);
if (r != 0)
{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
+			pg_log_error("could not stop postmaster: exit code was %d", r);
_exit(2);			/* not exit(), that could be recursive */
}

There's a lot of stuff like this. Perhaps worth doing separately? I'm not sure
I unerstand where you used bail and where not. I assume it's mostly arund use
uf _exit() vs exit()?

+ test_status_ok(tests[i]);

if (statuses[i] != 0)
log_child_failure(statuses[i]);

INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));

Based on the discussion downthread, let's just always compute this and display
it even in the tap format?

Greetings,

Andres Freund

On 4 Jul 2022, at 22:13, Andres Freund <andres@anarazel.de> wrote:

Hi,

On 2022-06-29 21:50:45 +0200, Daniel Gustafsson wrote:

@@ -279,8 +648,7 @@ stop_postmaster(void)
r = system(buf);
if (r != 0)
{
-			fprintf(stderr, _("\n%s: could not stop postmaster: exit code was %d\n"),
-					progname, r);
+			pg_log_error("could not stop postmaster: exit code was %d", r);
_exit(2);			/* not exit(), that could be recursive */
}

There's a lot of stuff like this. Perhaps worth doing separately? I'm not sure
I unerstand where you used bail and where not. I assume it's mostly arund use
uf _exit() vs exit()?

Since bail will cause the entire testrun to be considered a failure, the idea
was to avoid using bail() for any errors in tearing down the test harness after
an otherwise successful test run.

Moving to pg_log_error() can for sure be broken out into a separate patch from
the rest of the set (if we at all want to do that, but it seemed logical to
address when dealing with other output routines).

+ test_status_ok(tests[i]);

if (statuses[i] != 0)
log_child_failure(statuses[i]);

INSTR_TIME_SUBTRACT(stoptimes[i], starttimes[i]);
-			status(_(" %8.0f ms"), INSTR_TIME_GET_MILLISEC(stoptimes[i]));
+			runtime(tests[i], INSTR_TIME_GET_MILLISEC(stoptimes[i]));

Based on the discussion downthread, let's just always compute this and display
it even in the tap format?

Sure, it's easy enough to do and include in the test description. The reason I
left it out is that the test runners I played around with all hide those
details and only show a running total. That of course doesn't mean that all
runners will do that (and anyone running TAP output for human consumption will
want it), so I agree with putting it in, I'll fix that up in a v6 shortly.

--
Daniel Gustafsson https://vmware.com/

On 4 Jul 2022, at 16:27, Peter Eisentraut <peter.eisentraut@enterprisedb.com> wrote:

On 29.06.22 21:50, Daniel Gustafsson wrote:

Attached is a new version of this patch, which completes the TAP output format
option such that all codepaths emitting output are TAP compliant. The verbose
option is fixed to to not output extraneous newlines which the previous PoC
did. The output it made to conform to the original TAP spec since v13/14 TAP
parsers seem less common than those that can handle the original spec. Support
for the new format additions should be quite simple to add should we want that.
Running pg_regress --verbose should give the current format output.
I did end up combining TAP and --verbose into a single patch, as the TAP format
sort of depends on the verbose flag as TAP has no verbose mode. I can split it
into two separate should a reviewer prefer that.

I'm not sure what to make of all these options. I think providing a TAP output for pg_regress is a good idea. But then do we still need the old output? Is it worth maintaining two output formats that display exactly the same thing in slightly different ways?

If we believe that TAP is good enough for human consumption and not just as
input to test runners then we don't. Personally I think the traditional format
is more pleasant to read than raw TAP output when running tests.

What is the purpose of the --verbose option? When and how is one supposed to activate that? The proposed default format now hides the fact that some tests are started in parallel.

The discussion on this was in 20220221164736.rq3ornzjdkmwk2wo@alap3.anarazel.de
where it was proposed that we could cut the boilerplate. Thinking on it I
agree that the parallel run info should be included even without --verbose so
I'll add that back. In general, running with --verbose should ideally only be
required for troubleshooting setup/teardown issues with testing.

I remember the last time I wanted to tweak the output of the parallel tests, people were very attached to the particular timing and spacing of the current output. So I'm not sure people will like this.

The timing output is very popular. Where is that in the TAP output?

As I mentioned in the mail upthread, TAP runners generally hide that info and
only show a running total. That being said, I do agree with adding back so
I'll do that in a new version of the patch.

More generally, what do you envision we do with this feature? Who is it for, what are the tradeoffs, etc.?

In general, my thinking with this was that normal testruns started with make
check (or similar) by developers would use the traditional format (albeit less
verbose) and that the TAP output was for automated test runners in general and
the meson test runner in particular. The TAP format is an opt-in with the
traditional format being the default.

The tradeoff is of course that maintaining two output formats is more work than
maintaining one, but it's not really something we change all that often so that
might not be too heavy a burden.

I personally didn't see us replacing the traditional format for "human
readable" runs, if that's where the discussion is heading then the patch can
look quite different. Having test output format parity with supported back
branches seemed like a good idea to me at the time of writing at least.

--
Daniel Gustafsson https://vmware.com/

Andres Freund <andres@anarazel.de> writes:

Both of those things are fairly critical for test development. You
need to know what else might be running in parallel with a test case,
and you need to know whether you just bloated the runtime unreasonably.

That should be doable with tap as well - afaics the output of that could
nearly be the same as now, preceded by a #.

I don't mind minor changes like prefixing # --- I just don't want
to lose information.

regards, tom lane

On 4 Jul 2022, at 16:39, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Peter Eisentraut <peter.eisentraut@enterprisedb.com> writes:

I'm not sure what to make of all these options. I think providing a TAP
output for pg_regress is a good idea. But then do we still need the old
output? Is it worth maintaining two output formats that display exactly
the same thing in slightly different ways?

Probably is, because this is bad:

... The proposed default format now hides the
fact that some tests are started in parallel. I remember the last time
I wanted to tweak the output of the parallel tests, people were very
attached to the particular timing and spacing of the current output. So
I'm not sure people will like this.

and so is this:

The timing output is very popular. Where is that in the TAP output?

Both of those things are fairly critical for test development. You
need to know what else might be running in parallel with a test case,
and you need to know whether you just bloated the runtime unreasonably.

More generally, I'm unhappy about the proposal that TAP should become
the default output.

That's not my proposal though, my proposal is that the traditional format
should be the default output (with the parallel test info added back, that was
my bad), and that TAP is used in automated test runners like in meson. Hiding
the timing in TAP was (as mentioned upthread) since TAP test runners generally
never show that anyways, but I'll add it back since it clearly doesn't hurt to
have even there.

There is nothing particularly human-friendly
about it, whereas the existing format is something we have tuned to
our liking over literally decades. I don't mind if there's a way to
get TAP when you're actually intending to feed it into a TAP-parsing
tool, but I am not a TAP-parsing tool and I don't see why I should
have to put up with it.

I totally agree, and that's why the patch has the traditional format - without
all the boilerplate - as the default. Unless opting-in there is no change over
today, apart from the boilerplate.

--
Daniel Gustafsson https://vmware.com/

Hi,

On 2022-07-05 00:06:04 +0200, Daniel Gustafsson wrote:

On 4 Jul 2022, at 16:27, Peter Eisentraut <peter.eisentraut@enterprisedb.com> wrote:

On 29.06.22 21:50, Daniel Gustafsson wrote:

Attached is a new version of this patch, which completes the TAP output format
option such that all codepaths emitting output are TAP compliant. The verbose
option is fixed to to not output extraneous newlines which the previous PoC
did. The output it made to conform to the original TAP spec since v13/14 TAP
parsers seem less common than those that can handle the original spec. Support
for the new format additions should be quite simple to add should we want that.
Running pg_regress --verbose should give the current format output.
I did end up combining TAP and --verbose into a single patch, as the TAP format
sort of depends on the verbose flag as TAP has no verbose mode. I can split it
into two separate should a reviewer prefer that.

I'm not sure what to make of all these options. I think providing a TAP output for pg_regress is a good idea. But then do we still need the old output? Is it worth maintaining two output formats that display exactly the same thing in slightly different ways?

If we believe that TAP is good enough for human consumption and not just as
input to test runners then we don't. Personally I think the traditional format
is more pleasant to read than raw TAP output when running tests.

I think with a bit of care the tap output could be nearly the same
"quality". It might not be the absolute "purest" tap output, but who cares.

test tablespace ... ok 418 ms
parallel group (20 tests): oid char int2 varchar name int4 text pg_lsn regproc txid money boolean uuid float4 int8 float8 bit enum rangetypes numeric
boolean ... ok 34 ms
char ... ok 20 ms
name ... ok 26 ms

isn't that different from

ok 1 - tablespace 418ms
# parallel group (20 tests): oid char int2 varchar name int4 text pg_lsn regproc txid money boolean uuid float4 int8 float8 bit enum rangetypes numeric
ok 2 - boolean 34ms
ok 3 - char 20ms
ok 4 - name 26ms

or whatever.

For non-parallel tests I think we currently print the test name before running
the test, which obviously doesn't work well when needing to print the 'ok'
'not ok' first. We could just print
# non-parallel group tablespace
or such? That doesn't

I wonder if for parallel tests we should print the test number based on the
start of the test rather than the finish time? Hm, it also looks like it's
legal to just leave the test number out?

The discussion on this was in 20220221164736.rq3ornzjdkmwk2wo@alap3.anarazel.de
where it was proposed that we could cut the boilerplate.

I think that was more about things like CREATE DATABASE etc. And I'm not sure
we need an option to keep showing those details.

I remember the last time I wanted to tweak the output of the parallel tests, people were very attached to the particular timing and spacing of the current output. So I'm not sure people will like this.

The timing output is very popular. Where is that in the TAP output?

As I mentioned in the mail upthread, TAP runners generally hide that info and
only show a running total. That being said, I do agree with adding back so
I'll do that in a new version of the patch.

FWIW, meson's testrunner shows the individual tap output when using -v.

One test where using -v is a problem is pg_dump's tests - the absurd number of
8169 tests makes showing that decidedly not fun.

Having test output format parity with supported back branches seemed like a
good idea to me at the time of writing at least.

That's of course nice, but it also kind of corners us into not evolving the
default format, which I don't think is warranted...

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:

I think with a bit of care the tap output could be nearly the same
"quality". It might not be the absolute "purest" tap output, but who cares.

+1

For non-parallel tests I think we currently print the test name before running
the test, which obviously doesn't work well when needing to print the 'ok'
'not ok' first.

Is this still a consideration? We got rid of serial_schedule some
time ago.

I wonder if for parallel tests we should print the test number based on the
start of the test rather than the finish time?

I think we need the test number to be stable, so it had better be the
ordering appearing in the schedule file. But we already print the
results in that order.

regards, tom lane

Hi,

On 2022-07-04 21:56:24 -0400, Tom Lane wrote:

For non-parallel tests I think we currently print the test name before running
the test, which obviously doesn't work well when needing to print the 'ok'
'not ok' first.

Is this still a consideration? We got rid of serial_schedule some
time ago.

Not really for the main tests, there's a few serial steps, but not enough that
a bit additional output would be an issue. I think all tests in contrib are
serial though, and some have enough tests that it might be annoying?

I wonder if for parallel tests we should print the test number based on the
start of the test rather than the finish time?

I think we need the test number to be stable, so it had better be the
ordering appearing in the schedule file. But we already print the
results in that order.

I remembered some asynchronizity, but apparently that's just the "parallel
group" line.

Greetings,

Andres Freund

This entry has been waiting on author input for a while (our current
threshold is roughly two weeks), so I've marked it Returned with
Feedback.

Once you think the patchset is ready for review again, you (or any
interested party) can resurrect the patch entry by visiting

https://commitfest.postgresql.org/38/3559/

and changing the status to "Needs Review", and then changing the
status again to "Move to next CF". (Don't forget the second step;
hopefully we will have streamlined this in the near future!)

Thanks,
--Jacob