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 <and...@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 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..d92c31a891 100644 --- a/src/test/perl/PostgreSQL/Test/SimpleTee.pm +++ b/src/test/perl/PostgreSQL/Test/SimpleTee.pm @@ -10,10 +10,31 @@ # method is currently implemented; that's all we need. We don't want to # depend on IO::Tee just for this. +# The package is enhanced to add timestamp and elapsed time decorations to +# the log file traces sent through this interface from Test::More. + package PostgreSQL::Test::SimpleTee; use strict; use warnings; +use Time::HiRes qw(time); + +my $last_time; + +BEGIN { $last_time = time; } + +sub _time_str +{ + my $tm = time; + my $diff = $tm - $last_time; + $last_time = $tm; + my ($sec, $min, $hour, $mday, $mon, $year, $wday, $yday, $isdst) = + localtime($tm); + my $usec = int(1000 * ($tm - int($tm))); + return sprintf("[%.2d:%.2d:%.2d.%.3d](%.3fs) ", + $hour, $min, $sec, $usec, $diff); +} + sub TIEHANDLE { my $self = shift; @@ -24,10 +45,16 @@ sub PRINT { my $self = shift; my $ok = 1; + # The first file argument passed to tiehandle in PostgreSQL::Test::Utils is + # the original stdout, which is what PROVE sees. Additional decorations + # confuse it, so only put out the time string on files after the first. + my $skip = 1; + my $ts = _time_str; for my $fh (@$self) { - print $fh @_ or $ok = 0; + print $fh ($skip ? "" : $ts), @_ or $ok = 0; $fh->flush or $ok = 0; + $skip = 0; } return $ok; }