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;
}
