tests: Output test time to trs files

Observed issue
==============

The test suite for lttng-tools is relatively large and can take
upwards of an hour or more to run in CI, especially with root
tests enabled.

Neither automake driver (`tests/utils/tap-driver.sh`) nor the
standalone tap script (`tests/utils/tap/tap.sh`) provide timing
information for the test runs or the steps within a test run.

Solution
========

The TAP driver invoked by `make check` has been modified to include a
`:time-taken:` metadata field (in seconds) in the produced trs file.

Known drawbacks
===============

`date` on FreeBSD does not support the `%N` formatter for nanoseconds,
which results in the precision dropping to 1s.

Metadata which isn't recognized by the automake test harness is
currently ignored, but it is a behaviour that remains open to change.

C.f. https://www.gnu.org/software/automake/manual/html_node/Log-files-generation-and-test-results-recording.html

Further work is required on the CI side to make use of the information.

Signed-off-by: Kienan Stewart <kstewart@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: I94c7ddd7eb9388c595794e76dbbedc9bfe64d206

diff --git a/tests/utils/tap-driver.sh b/tests/utils/tap-driver.sh
index 65037ab65f5dfb03d729704d0132217b66091053..cbe2952210223ce6dc46f9d42da2cb2f60263d1b 100755 (executable)
--- a/tests/utils/tap-driver.sh
+++ b/tests/utils/tap-driver.sh
@@ -211,6 +211,17 @@ function copy_in_global_log()
   return 0
 }
 
+function gettime_ns(    r,    cmd)
+{
+   cmd = "date +%s.%N"
+   r = ""
+   if (cmd | getline r) {
+     r = r
+   }
+   close(cmd)
+   return sprintf("%f", r)
+}
+
 function get_global_test_result()
 {
     if ("ERROR" in test_results_seen)
@@ -482,6 +493,7 @@ function write_test_results()
   print ":global-test-result: " get_global_test_result() > trs_file
   print ":recheck: "  yn(must_recheck()) > trs_file
   print ":copy-in-global-log: " yn(copy_in_global_log()) > trs_file
+  print ":time-taken: " sprintf("%f", gettime_ns() - TIME_START) > trs_file
   for (i = 0; i < test_results_index; i += 1)
     print ":test-result: " test_results_list[i] > trs_file
   close(trs_file);
@@ -515,6 +527,7 @@ bailed_out = 0 # Whether a "Bail out!" directive has been seen.
 # it is ("early" is seen before any test result, "late" otherwise).
 plan_seen = NO_PLAN
 
+TIME_START = gettime_ns();
 ## --------- ##
 ##  PARSING  ##
 ## --------- ##