Re: Can we automatically add elapsed times to tap test log? - Mailing list pgsql-hackers

From Andrew Dunstan
Subject Re: Can we automatically add elapsed times to tap test log?
Date
Msg-id 96c7dee1-3c59-ada5-7669-d7106e4d53e5@dunslane.net
Whole thread Raw
In response to Re: Can we automatically add elapsed times to tap test log?  (Andrew Dunstan <andrew@dunslane.net>)
Responses Re: Can we automatically add elapsed times to tap test log?  (Andres Freund <andres@anarazel.de>)
List pgsql-hackers
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




pgsql-hackers by date:

Previous
From: Etsuro Fujita
Date:
Subject: Re: Defer selection of asynchronous subplans until the executor initialization stage
Next
From: Zhihong Yu
Date:
Subject: Re: Defer selection of asynchronous subplans until the executor initialization stage