From e73b293111eacc3c0f6eca0009ac3afa51ea85f1 Mon Sep 17 00:00:00 2001 From: Kienan Stewart Date: Wed, 23 Aug 2023 14:43:54 -0400 Subject: [PATCH] tests: Output test time to trs files MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit 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 Signed-off-by: Jérémie Galarneau Change-Id: I94c7ddd7eb9388c595794e76dbbedc9bfe64d206 --- tests/utils/tap-driver.sh | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/tests/utils/tap-driver.sh b/tests/utils/tap-driver.sh index 65037ab65..cbe295221 100755 --- 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 ## ## --------- ## -- 2.34.1