On 4/1/22 16:25, Andrew Dunstan wrote: > 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. > >
Here's a version that actually works. It produces traces that look like this: andrew@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 cheers andrew -- Andrew Dunstan EDB: https://www.enterprisedb.com
diff --git a/src/test/perl/PostgreSQL/Test/SimpleTee.pm b/src/test/perl/PostgreSQL/Test/SimpleTee.pm index bb9d79a755..432a458d09 100644 --- a/src/test/perl/PostgreSQL/Test/SimpleTee.pm +++ b/src/test/perl/PostgreSQL/Test/SimpleTee.pm @@ -14,6 +14,18 @@ package PostgreSQL::Test::SimpleTee; use strict; use warnings; +my $start_time; + +BEGIN { $start_time = time; } + +sub _time_str +{ + my ($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = + localtime(time); + return sprintf("[%.2d:%.2d:%.2d](%ds) ", + $hour, $min, $sec, time - $start_time); +} + sub TIEHANDLE { my $self = shift; @@ -24,10 +36,13 @@ sub PRINT { my $self = shift; my $ok = 1; + # skip the timestamp on the first file handle so PROVE doesn't get upset + my $skip = 1; for my $fh (@$self) { - print $fh @_ or $ok = 0; + print $fh ($skip ? "" :_time_str), @_ or $ok = 0; $fh->flush or $ok = 0; + $skip = 0; } return $ok; }