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

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(at)anarazel(dot)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(at)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