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 <[email protected]> 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;
}
