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

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

In the absence of further comment I have pushed this.

cheers

andrew

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