Horton

Thread

Commits

  1. Add timestamp and elapsed time decorations to TAP test logs

  1. Can we automatically add elapsed times to tap test log?

    Andres Freund <andres@anarazel.de> — 2022-04-01T17:21:50Z

    Hi,

right now I am looking at a test added in the shmstats patch that's slow on
CI, on windows only. Unfortunately the regress_log_* output is useless as-is
to figure out where things hang.

I've hit this several times before. Of course it's not too hard to hack up
something printing elapsed time. But ISTM that it'd be better if we were able
to prefix the logging into regress_log_* with something like
[timestamp + time since start of test]
or
[timestamp + time since start of test + time since last log message]


This isn't just useful to figure out what parts of test are slow, but also
helps correlate server logs with the regress_log_* output. Which right now is
hard and inaccurate, requiring manually correlating statements between server
log and the tap test (often there's no logging for statements in the
regress_log_*).

Greetings,

Andres Freund

  2. Re: Can we automatically add elapsed times to tap test log?

    Nathan Bossart <nathandbossart@gmail.com> — 2022-04-01T17:44:09Z

    On Fri, Apr 01, 2022 at 10:21:50AM -0700, Andres Freund wrote:
> right now I am looking at a test added in the shmstats patch that's slow on
> CI, on windows only. Unfortunately the regress_log_* output is useless as-is
> to figure out where things hang.
> 
> I've hit this several times before. Of course it's not too hard to hack up
> something printing elapsed time. But ISTM that it'd be better if we were able
> to prefix the logging into regress_log_* with something like
> [timestamp + time since start of test]
> or
> [timestamp + time since start of test + time since last log message]
> 
> 
> This isn't just useful to figure out what parts of test are slow, but also
> helps correlate server logs with the regress_log_* output. Which right now is
> hard and inaccurate, requiring manually correlating statements between server
> log and the tap test (often there's no logging for statements in the
> regress_log_*).

+1

-- 
Nathan Bossart
Amazon Web Services: https://aws.amazon.com

  3. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-01T19:16:28Z

    On 4/1/22 13:44, Nathan Bossart wrote:
> On Fri, Apr 01, 2022 at 10:21:50AM -0700, Andres Freund wrote:
>> right now I am looking at a test added in the shmstats patch that's slow on
>> CI, on windows only. Unfortunately the regress_log_* output is useless as-is
>> to figure out where things hang.
>>
>> I've hit this several times before. Of course it's not too hard to hack up
>> something printing elapsed time. But ISTM that it'd be better if we were able
>> to prefix the logging into regress_log_* with something like
>> [timestamp + time since start of test]
>> or
>> [timestamp + time since start of test + time since last log message]
>>
>>
>> This isn't just useful to figure out what parts of test are slow, but also
>> helps correlate server logs with the regress_log_* output. Which right now is
>> hard and inaccurate, requiring manually correlating statements between server
>> log and the tap test (often there's no logging for statements in the
>> regress_log_*).
> +1
>


Maybe one way would be to make a change in
src/test/perl/PostgreSQL/Test/SimpleTee.pm. The simplest thing would
just be to add a timestamp, the other things would involve a bit more
bookkeeping. It should also be checked to make sure it doesn't add too
much overhead, although I would be surprised if it did.


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  4. Re: Can we automatically add elapsed times to tap test log?

    Andres Freund <andres@anarazel.de> — 2022-04-01T19:29:33Z

    Hi,

On 2022-04-01 10:21:50 -0700, Andres Freund wrote:
> right now I am looking at a test added in the shmstats patch that's slow on
> CI, on windows only. Unfortunately the regress_log_* output is useless as-is
> to figure out where things hang.

<two hours of debugging later>

This turns out to be a problem somewhere in the tap testing infrastructure,
rather than the test itself. The slow thing wasn't anything the test did. All
the time is spent in an is().  To verify that, I added a bunch of

ok(1, "this is some long output to test a theory");
print_time();

a few tests before the slow test. And:

ok 7 - this is some long output to test a theory
# test theory 1: 0.000 sec
ok 8 - this is some long output to test a theory
# test theory 2: 0.000 sec
ok 9 - this is some long output to test a theory
# test theory 3: 40.484 sec
ok 10 - this is some long output to test a theory
# test theory 4: 0.001 sec
ok 11 - this is some long output to test a theory
# test theory 5: 0.000 sec

The problem also vanishes when running tests without PROVE_FLAGS=-j$something


What this looks like to me is that when running tests concurrently, the buffer
of the file descriptor used to report tap test output fills up. The blocked
test can only progress once prove gets around to reading from that fd,
presumably when another test finishes.

Gah. I want my time back.


I can't reproduce a similar issue on linux. But of course I'm using a newer
perl, and it's likely a timing dependent issue, so it's not guaranteed to be a
windows problem. But ...


Greetings,

Andres Freund

  5. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-01T20:25:44Z

    On 4/1/22 15:16, Andrew Dunstan wrote:
> On 4/1/22 13:44, Nathan Bossart wrote:
>> On Fri, Apr 01, 2022 at 10:21:50AM -0700, Andres Freund wrote:
>>> right now I am looking at a test added in the shmstats patch that's slow on
>>> CI, on windows only. Unfortunately the regress_log_* output is useless as-is
>>> to figure out where things hang.
>>>
>>> I've hit this several times before. Of course it's not too hard to hack up
>>> something printing elapsed time. But ISTM that it'd be better if we were able
>>> to prefix the logging into regress_log_* with something like
>>> [timestamp + time since start of test]
>>> or
>>> [timestamp + time since start of test + time since last log message]
>>>
>>>
>>> This isn't just useful to figure out what parts of test are slow, but also
>>> helps correlate server logs with the regress_log_* output. Which right now is
>>> hard and inaccurate, requiring manually correlating statements between server
>>> log and the tap test (often there's no logging for statements in the
>>> regress_log_*).
>> +1
>>
>
> Maybe one way would be to make a change in
> src/test/perl/PostgreSQL/Test/SimpleTee.pm. The simplest thing would
> just be to add a timestamp, the other things would involve a bit more
> bookkeeping. It should also be checked to make sure it doesn't add too
> much overhead, although I would be surprised if it did.
>


Along these lines. Untested, it clearly needs a bit of polish (e.g. a
way to turn it on or off for a filehandle). We could use Time::Hires if
you want higher resolution times.


cheers


andrew


--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  6. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-02T10:57:20Z

    On 4/1/22 16:25, Andrew Dunstan wrote:
> On 4/1/22 15:16, Andrew Dunstan wrote:
>> On 4/1/22 13:44, Nathan Bossart wrote:
>>> On Fri, Apr 01, 2022 at 10:21:50AM -0700, Andres Freund wrote:
>>>> right now I am looking at a test added in the shmstats patch that's slow on
>>>> CI, on windows only. Unfortunately the regress_log_* output is useless as-is
>>>> to figure out where things hang.
>>>>
>>>> I've hit this several times before. Of course it's not too hard to hack up
>>>> something printing elapsed time. But ISTM that it'd be better if we were able
>>>> to prefix the logging into regress_log_* with something like
>>>> [timestamp + time since start of test]
>>>> or
>>>> [timestamp + time since start of test + time since last log message]
>>>>
>>>>
>>>> This isn't just useful to figure out what parts of test are slow, but also
>>>> helps correlate server logs with the regress_log_* output. Which right now is
>>>> hard and inaccurate, requiring manually correlating statements between server
>>>> log and the tap test (often there's no logging for statements in the
>>>> regress_log_*).
>>> +1
>>>
>> Maybe one way would be to make a change in
>> src/test/perl/PostgreSQL/Test/SimpleTee.pm. The simplest thing would
>> just be to add a timestamp, the other things would involve a bit more
>> bookkeeping. It should also be checked to make sure it doesn't add too
>> much overhead, although I would be surprised if it did.
>>
>
> Along these lines. Untested, it clearly needs a bit of polish (e.g. a
> way to turn it on or off for a filehandle). We could use Time::Hires if
> you want higher resolution times.
>
>


Here's a version that actually works. It produces traces that look like
this:


andrew@emma:pg_upgrade $ grep '([0-9]*s)'
tmp_check/log/regress_log_002_pg_upgrade
[21:55:06](63s) ok 1 - dump before running pg_upgrade
[21:55:22](79s) ok 2 - run of pg_upgrade for new instance
[21:55:27](84s) ok 3 - old and new dumps match after pg_upgrade
[21:55:27](84s) 1..3


cheers


andrew

--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  7. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-07T21:02:40Z

    On 4/2/22 06:57, Andrew Dunstan wrote:
> Here's a version that actually works. It produces traces that look like
> this:
>
>
> andrew@emma:pg_upgrade $ grep '([0-9]*s)'
> tmp_check/log/regress_log_002_pg_upgrade
> [21:55:06](63s) ok 1 - dump before running pg_upgrade
> [21:55:22](79s) ok 2 - run of pg_upgrade for new instance
> [21:55:27](84s) ok 3 - old and new dumps match after pg_upgrade
> [21:55:27](84s) 1..3
>

I know there's a lot going on, but are people interested in this? It's a
pretty small patch to produce something that seems quite useful.


cheers


andrew



--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  8. Re: Can we automatically add elapsed times to tap test log?

    Tom Lane <tgl@sss.pgh.pa.us> — 2022-04-07T21:21:09Z

    Andrew Dunstan <andrew@dunslane.net> writes:
> On 4/2/22 06:57, Andrew Dunstan wrote:
>> Here's a version that actually works. It produces traces that look like
>> this:
>> andrew@emma:pg_upgrade $ grep '([0-9]*s)'
>> tmp_check/log/regress_log_002_pg_upgrade
>> [21:55:06](63s) ok 1 - dump before running pg_upgrade
>> [21:55:22](79s) ok 2 - run of pg_upgrade for new instance
>> [21:55:27](84s) ok 3 - old and new dumps match after pg_upgrade
>> [21:55:27](84s) 1..3

> I know there's a lot going on, but are people interested in this? It's a
> pretty small patch to produce something that seems quite useful.

I too think that the elapsed time is useful.  I'm less convinced
that the time-of-day marker is useful.

It also seems kind of odd that the elapsed time accumulates rather
than being reset for each line.  As it stands one would be doing a lot
of mental subtractions rather than being able to see directly how long
each step takes.  I suppose that on fast machines where each step is
under one second, accumulation would be more useful than printing a
lot of zeroes --- but on the other hand, those aren't the cases where
you're going to be terribly concerned about the runtime.

			regards, tom lane

  9. Re: Can we automatically add elapsed times to tap test log?

    Andres Freund <andres@anarazel.de> — 2022-04-07T21:38:35Z

    Hi,

On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
> > On 4/2/22 06:57, Andrew Dunstan wrote:
> >> Here's a version that actually works. It produces traces that look like
> >> this:
> >> andrew@emma:pg_upgrade $ grep '([0-9]*s)'
> >> tmp_check/log/regress_log_002_pg_upgrade
> >> [21:55:06](63s) ok 1 - dump before running pg_upgrade
> >> [21:55:22](79s) ok 2 - run of pg_upgrade for new instance
> >> [21:55:27](84s) ok 3 - old and new dumps match after pg_upgrade
> >> [21:55:27](84s) 1..3
> 
> > I know there's a lot going on, but are people interested in this? It's a
> > pretty small patch to produce something that seems quite useful.

It's been 0 days since I last wanted this.


> I too think that the elapsed time is useful.  I'm less convinced
> that the time-of-day marker is useful.

I think it'd be quite useful if it had more precision - it's a pita to
correlate regress_log_* output with server logs.


> It also seems kind of odd that the elapsed time accumulates rather
> than being reset for each line.  As it stands one would be doing a lot
> of mental subtractions rather than being able to see directly how long
> each step takes.  I suppose that on fast machines where each step is
> under one second, accumulation would be more useful than printing a
> lot of zeroes --- but on the other hand, those aren't the cases where
> you're going to be terribly concerned about the runtime.

I like both - if you want to find where the slowdown among a lot of log lines
is, it's easier to look at the time accumulated elapsed time. If you actually
want to see how long individual things take, non-accumulated is more useful.

I've printed both in the past...

Any chance we could print higher res time?

Greetings,

Andres Freund

  10. Re: Can we automatically add elapsed times to tap test log?

    Tom Lane <tgl@sss.pgh.pa.us> — 2022-04-07T21:45:09Z

    Andres Freund <andres@anarazel.de> writes:
> On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
>> I too think that the elapsed time is useful.  I'm less convinced
>> that the time-of-day marker is useful.

> I think it'd be quite useful if it had more precision - it's a pita to
> correlate regress_log_* output with server logs.

Fair point.  Maybe we could keep the timestamp (with ms precision
if possible) and then the parenthetical bit is time-since-last-line
(also with ms precision)?  I think that would more or less satisfy
both uses.

			regards, tom lane

  11. Re: Can we automatically add elapsed times to tap test log?

    Andres Freund <andres@anarazel.de> — 2022-04-07T21:58:07Z

    Hi,

On 2022-04-07 17:45:09 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
> >> I too think that the elapsed time is useful.  I'm less convinced
> >> that the time-of-day marker is useful.
> 
> > I think it'd be quite useful if it had more precision - it's a pita to
> > correlate regress_log_* output with server logs.
> 
> Fair point.  Maybe we could keep the timestamp (with ms precision
> if possible) and then the parenthetical bit is time-since-last-line
> (also with ms precision)?  I think that would more or less satisfy
> both uses.

Would work for me...

Greetings,

Andres Freund

  12. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-07T23:55:11Z

    On 4/7/22 17:58, Andres Freund wrote:
> Hi,
>
> On 2022-04-07 17:45:09 -0400, Tom Lane wrote:
>> Andres Freund <andres@anarazel.de> writes:
>>> On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
>>>> I too think that the elapsed time is useful.  I'm less convinced
>>>> that the time-of-day marker is useful.
>>> I think it'd be quite useful if it had more precision - it's a pita to
>>> correlate regress_log_* output with server logs.
>> Fair point.  Maybe we could keep the timestamp (with ms precision
>> if possible) and then the parenthetical bit is time-since-last-line
>> (also with ms precision)?  I think that would more or less satisfy
>> both uses.
> Would work for me...
>

All doable. Time::HiRes gives us a higher resolution timer. I'll post a
new version in a day or two.


cheers


andrew


--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  13. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-08T13:51:33Z

    On 4/7/22 19:55, Andrew Dunstan wrote:
> On 4/7/22 17:58, Andres Freund wrote:
>> Hi,
>>
>> On 2022-04-07 17:45:09 -0400, Tom Lane wrote:
>>> Andres Freund <andres@anarazel.de> writes:
>>>> On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
>>>>> I too think that the elapsed time is useful.  I'm less convinced
>>>>> that the time-of-day marker is useful.
>>>> I think it'd be quite useful if it had more precision - it's a pita to
>>>> correlate regress_log_* output with server logs.
>>> Fair point.  Maybe we could keep the timestamp (with ms precision
>>> if possible) and then the parenthetical bit is time-since-last-line
>>> (also with ms precision)?  I think that would more or less satisfy
>>> both uses.
>> Would work for me...
>>
> All doable. Time::HiRes gives us a higher resolution timer. I'll post a
> new version in a day or two.


New version attached.


Sample traces:


andrew@emma:log $ egrep '^\[[0-9][0-9]:[00-9][0-9]:' regress_log_020_pg_receivewal | tail -n 15
[09:22:45.031](0.000s) ok 30 # skip postgres was not built with LZ4 support
[09:22:45.032](0.000s) ok 31 # skip postgres was not built with LZ4 support
[09:22:45.296](0.265s) ok 32 - streaming some WAL
[09:22:45.297](0.001s) ok 33 - check that previously partial WAL is now complete
[09:22:45.298](0.001s) ok 34 - check stream dir permissions
[09:22:45.298](0.000s) # Testing pg_receivewal with slot as starting streaming point
[09:22:45.582](0.284s) ok 35 - pg_receivewal fails with non-existing slot: exit code not 0
[09:22:45.583](0.001s) ok 36 - pg_receivewal fails with non-existing slot: matches
[09:22:45.618](0.036s) ok 37 - WAL streamed from the slot's restart_lsn
[09:22:45.619](0.001s) ok 38 - WAL from the slot's restart_lsn has been archived
[09:22:46.597](0.978s) ok 39 - Stream some wal after promoting, resuming from the slot's position
[09:22:46.598](0.001s) ok 40 - WAL segment 00000001000000000000000B archived after timeline jump
[09:22:46.598](0.000s) ok 41 - WAL segment 00000002000000000000000C archived after timeline jump
[09:22:46.598](0.000s) ok 42 - timeline history file archived after timeline jump
[09:22:46.599](0.001s) 1..42


cheers


andrew


--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  14. Re: Can we automatically add elapsed times to tap test log?

    Andrew Dunstan <andrew@dunslane.net> — 2022-04-10T13:23:16Z

    On 4/8/22 09:51, Andrew Dunstan wrote:
> On 4/7/22 19:55, Andrew Dunstan wrote:
>> On 4/7/22 17:58, Andres Freund wrote:
>>> Hi,
>>>
>>> On 2022-04-07 17:45:09 -0400, Tom Lane wrote:
>>>> Andres Freund <andres@anarazel.de> writes:
>>>>> On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
>>>>>> I too think that the elapsed time is useful.  I'm less convinced
>>>>>> that the time-of-day marker is useful.
>>>>> I think it'd be quite useful if it had more precision - it's a pita to
>>>>> correlate regress_log_* output with server logs.
>>>> Fair point.  Maybe we could keep the timestamp (with ms precision
>>>> if possible) and then the parenthetical bit is time-since-last-line
>>>> (also with ms precision)?  I think that would more or less satisfy
>>>> both uses.
>>> Would work for me...
>>>
>> All doable. Time::HiRes gives us a higher resolution timer. I'll post a
>> new version in a day or two.
>
> New version attached.
>
>
> Sample traces:
>
>
> andrew@emma:log $ egrep '^\[[0-9][0-9]:[00-9][0-9]:' regress_log_020_pg_receivewal | tail -n 15
> [09:22:45.031](0.000s) ok 30 # skip postgres was not built with LZ4 support
> [09:22:45.032](0.000s) ok 31 # skip postgres was not built with LZ4 support
> [09:22:45.296](0.265s) ok 32 - streaming some WAL
> [09:22:45.297](0.001s) ok 33 - check that previously partial WAL is now complete
> [09:22:45.298](0.001s) ok 34 - check stream dir permissions
> [09:22:45.298](0.000s) # Testing pg_receivewal with slot as starting streaming point
> [09:22:45.582](0.284s) ok 35 - pg_receivewal fails with non-existing slot: exit code not 0
> [09:22:45.583](0.001s) ok 36 - pg_receivewal fails with non-existing slot: matches
> [09:22:45.618](0.036s) ok 37 - WAL streamed from the slot's restart_lsn
> [09:22:45.619](0.001s) ok 38 - WAL from the slot's restart_lsn has been archived
> [09:22:46.597](0.978s) ok 39 - Stream some wal after promoting, resuming from the slot's position
> [09:22:46.598](0.001s) ok 40 - WAL segment 00000001000000000000000B archived after timeline jump
> [09:22:46.598](0.000s) ok 41 - WAL segment 00000002000000000000000C archived after timeline jump
> [09:22:46.598](0.000s) ok 42 - timeline history file archived after timeline jump
> [09:22:46.599](0.001s) 1..42
>
>


In the absence of further comment I have pushed this.


cheers


andrew


--
Andrew Dunstan
EDB: https://www.enterprisedb.com

  15. Re: Can we automatically add elapsed times to tap test log?

    Andres Freund <andres@anarazel.de> — 2022-04-10T16:43:30Z

    On 2022-04-10 09:23:16 -0400, Andrew Dunstan wrote:
> In the absence of further comment I have pushed this.

Thanks!