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

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