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

Hi,

On 2022-04-07 17:21:09 -0400, Tom Lane wrote:
> Andrew Dunstan <andrew(at)dunslane(dot)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(at)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