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

diff --git a/src/test/perl/PostgreSQL/Test/SimpleTee.pm b/src/test/perl/PostgreSQL/Test/SimpleTee.pm
index bb9d79a755636863ed405bc91f177864b7f12d96..7cb8591fed2e339fc700f260571ff7c9a6e87677 100644 (file)
--- 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;
 }