From 3b0a42e74edfc57c3cef1f3b1a583d4fe5cca846 Mon Sep 17 00:00:00 2001 From: Andrew Dunstan Date: Sun, 10 Apr 2022 08:46:12 -0400 Subject: [PATCH] Add timestamp and elapsed time decorations to TAP test logs These apply to traces from Test::More functions such as ok(), is(), diag() and note(). Output from other sources (e.g. external programs such a initdb) is not affected. The elapsed time is the time since the last such trace (or the beginning of the test in the first case). Times and timestamps are at millisecond precision. Discussion: https://postgr.es/m/20220401172150.rsycz4lrn7ewruil@alap3.anarazel.de --- src/test/perl/PostgreSQL/Test/SimpleTee.pm | 30 +++++++++++++++++++++- 1 file changed, 29 insertions(+), 1 deletion(-) diff --git a/src/test/perl/PostgreSQL/Test/SimpleTee.pm b/src/test/perl/PostgreSQL/Test/SimpleTee.pm index bb9d79a7556..7cb8591fed2 100644 --- a/src/test/perl/PostgreSQL/Test/SimpleTee.pm +++ b/src/test/perl/PostgreSQL/Test/SimpleTee.pm @@ -10,10 +10,32 @@ # 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 functions +# (ok, is, note, diag etc.). Elapsed time is shown as the time since the last +# log trace. + 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) = localtime($tm); + my $msec = int(1000 * ($tm - int($tm))); + return sprintf("[%.2d:%.2d:%.2d.%.3d](%.3fs) ", + $hour, $min, $sec, $msec, $diff); +} + sub TIEHANDLE { my $self = shift; @@ -24,10 +46,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; } -- 2.39.5