Add timestamp and elapsed time decorations to TAP test logs

adunstan · adunstan · commit 3b0a42e74edf · 2022-04-10T09:19:09.000-04:00
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
@@ -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;
 }
