From 2a69bf1437eb7e81979a1410b1a66a960b52caeb Mon Sep 17 00:00:00 2001 From: Kienan Stewart Date: Fri, 25 Aug 2023 15:31:16 -0400 Subject: [PATCH] tests: Automatically time TAP tests MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Output approximate test timing by default for TAP tests by initializing a timer when then TAP tests plan is initialized, and resetting after every result. Automatic timing of tests may be disabled by setting `TAP_AUTOTIME=0` in the environment. In `tap.sh`, `autotime` is provided as a public command to update configuration at runtime. tap.sh and the tap-driver.sh scripts use a small helper `tests/utils/tap/clock` to print the result of `lttng_clock_gettime`. Originally `date` was used, but there are two principal drawbacks: * the `%N` formatter to provided sub-second resolution is specific to GNU date, and unavailable on other platforms (eg. FreeBSD). * destructive tests that modify the system date would cause strange results (eg. a test that takes 10 years to run) Known drawbacks =============== The automatic timing depends on having plan called first. If plan isn't called (eg. in a late plan mode), the first test time will be wrong. The duration key is hardcoded to "duration_ms", as used by https://github.com/jenkinsci/tap-plugin As the timing information for the TAP tests is stored in a multiline YAML block following the result line, any unexpected output (eg. from stderr) could be written in that region. These lines can cause tools parsing the TAP log to fail as the lines written may not be valid YAML. For ci.lttng.org, the TAP parser should be configured to remove invalid YAML instead of causing the build to become "unstable". After a test run, lines other than `duration_ms` in the TAP YAML block can be identified with the following command: find . -iname '*.log' -exec sed -n '/ ---/,/ \.\.\./p' {} \; \ | grep -v -E ' ---| \.\.\.| duration_ms' Some solutions to the above issue were considered and discarded: * Using a named pipe to pass stderr through sed so lines may be prefixed with '# ' * Switching the `tap-driver.sh` to run with bash and take advantage of the Process substition for performing the prefixing of '# ' The above options ended up causing more coherency issues in the output file than were resolved due to differing types of buffering and processing delays. * Redirection to the stderr of the test script to another file The '*.log' and '*.trs' cleanups are driven by the automake log driver implementation, which is not aware of other files that may be produced during the invocation of the modified `tap-driver.sh`. I didn't find an easy way to hook into the automake behaviour to add additional file patterns to cleanup. * Cleanup in the various test scripts to systematically prefix stderr, or to respect the `ERROR_OUTPUT_DEST` of `tests/utils/utils.sh`. The scope of the patch would be significantly increased and for relatively low added value compared to instructing the CI systems to discard invalid YAML. Furthermore the values `OUTPUT_DEST` and `ERROR_OUTPUT_DEST` are set to `/dev/null`, which would further reduce the ability to understand failures based on the test logs. Signed-off-by: Kienan Stewart Signed-off-by: Jérémie Galarneau Change-Id: Iabc35fc00f14085ef035d4b4e19a2c30cd86d851 --- .gitignore | 1 + tests/utils/lttngtest/tap_generator.py | 10 +++++++ tests/utils/tap-driver.sh | 18 ++++++++---- tests/utils/tap/Makefile.am | 6 ++++ tests/utils/tap/clock.cpp | 18 ++++++++++++ tests/utils/tap/tap.c | 31 +++++++++++++++++++++ tests/utils/tap/tap.h | 2 ++ tests/utils/tap/tap.sh | 38 +++++++++++++++++++++++++- tests/utils/test_utils.py | 17 ++++++++++++ tests/utils/utils.cpp | 2 +- tests/utils/utils.h | 3 +- 11 files changed, 138 insertions(+), 8 deletions(-) create mode 100644 tests/utils/tap/clock.cpp diff --git a/.gitignore b/.gitignore index ca36c537b..eb2873e01 100644 --- a/.gitignore +++ b/.gitignore @@ -135,6 +135,7 @@ compile_commands.json /tests/regression/ust/multi-lib/exec-with-callsites /tests/regression/ust/multi-lib/exec-without-callsites /tests/utils/testapp/gen-data-pending/gen-data-pending +/tests/utils/tap/clock /tests/utils/testapp/gen-syscall-events-callstack/gen-syscall-events-callstack /tests/utils/testapp/gen-ust-events/gen-ust-events /tests/utils/testapp/gen-ust-events-ns/gen-ust-events-ns diff --git a/tests/utils/lttngtest/tap_generator.py b/tests/utils/lttngtest/tap_generator.py index 39c6bda90..f87c8c88b 100644 --- a/tests/utils/lttngtest/tap_generator.py +++ b/tests/utils/lttngtest/tap_generator.py @@ -6,7 +6,9 @@ # import contextlib +import os import sys +import time from typing import Iterator, Optional @@ -70,6 +72,10 @@ class TapGenerator: self._last_test_case_id = 0 # type: int self._printed_plan = False # type: bool self._has_failure = False # type: bool + self._time_tests = True # type: bool + if os.getenv("TAP_AUTOTIME", "1") == "" or os.getenv("TAP_AUTOTIME", "1") == "0": + self._time_tests = False + self._last_time = time.monotonic_ns() def __del__(self): if self.remaining_test_cases > 0: @@ -123,6 +129,7 @@ class TapGenerator: def test(self, result, description): # type: (bool, str) -> None + duration = (time.monotonic_ns() - self._last_time) / 1_000_000 if self._last_test_case_id == self._total_test_count: raise InvalidTestPlan("Executing too many tests") @@ -138,6 +145,9 @@ class TapGenerator: description=description, ) ) + if self._time_tests: + self._print("---\n duration_ms: {}\n...\n".format(duration)) + self._last_time = time.monotonic_ns() def ok(self, description): # type: (str) -> None diff --git a/tests/utils/tap-driver.sh b/tests/utils/tap-driver.sh index cbe295221..1e61e1f28 100755 --- a/tests/utils/tap-driver.sh +++ b/tests/utils/tap-driver.sh @@ -117,6 +117,8 @@ else init_colors='' fi +TIME_SCRIPT="$(realpath -e -- "$(dirname "$0")")/tap/clock" + # :; is there to work around a bug in bash 3.2 (and earlier) which # does not always set '$?' properly on redirection failure. # See the Autoconf manual for more details. @@ -142,7 +144,13 @@ fi else exec 2>&3 fi - "$@" + # Since stderr and stdout may go to the same file and the script + # may run in situations with different types of buffering, enforce + # line buffering for both FDs. This helps to prevent interleave between + # the outputs in the resulting file for half written lines, eg. + # ok 93 - Tes# PERROR - xxxx + # t some function + stdbuf -eL -oL -- "$@" echo $? ) | LC_ALL=C ${AM_TAP_AWK-awk} \ -v me="$me" \ @@ -154,6 +162,7 @@ fi -v ignore_exit="$ignore_exit" \ -v comments="$comments" \ -v diag_string="$diag_string" \ + -v time_script="${TIME_SCRIPT}" \ ' # TODO: the usages of "cat >&3" below could be optimized when using # GNU awk, and/on on systems that supports /dev/fd/. @@ -211,14 +220,13 @@ function copy_in_global_log() return 0 } -function gettime_ns( r, cmd) +function gettime_ns( r) { - cmd = "date +%s.%N" r = "" - if (cmd | getline r) { + if (time_script | getline r) { r = r } - close(cmd) + close(time_script) return sprintf("%f", r) } diff --git a/tests/utils/tap/Makefile.am b/tests/utils/tap/Makefile.am index f84d91c8a..a914b7813 100644 --- a/tests/utils/tap/Makefile.am +++ b/tests/utils/tap/Makefile.am @@ -1,7 +1,13 @@ # SPDX-License-Identifier: GPL-2.0-only +AM_CPPFLAGS += -I$(top_srcdir)/src/ -I$(top_srcdir)/include + +noinst_PROGRAMS = clock +clock_SOURCES = clock.cpp +clock_CPPFLAGS = $(AM_CPPFLAGS) noinst_LTLIBRARIES = libtap.la libtap_la_SOURCES = tap.c tap.h +libtap_la_LIBADD = ../libtestutils.la dist_noinst_SCRIPTS = tap.sh EXTRA_DIST = tap.sh diff --git a/tests/utils/tap/clock.cpp b/tests/utils/tap/clock.cpp new file mode 100644 index 000000000..5a99ddda0 --- /dev/null +++ b/tests/utils/tap/clock.cpp @@ -0,0 +1,18 @@ +/** + * Copyright (C) 2023 Kienan Stewart + * + * SPDX-License-Identifier: LGPL-2.1-only + */ + +#include "common/time.hpp" + +#include + +int main() { + struct timespec t; + int ret = lttng_clock_gettime(CLOCK_MONOTONIC, &t); + if (ret == 0) { + printf("%ld.%09ld\n", t.tv_sec, t.tv_nsec); + } + return ret; +} diff --git a/tests/utils/tap/tap.c b/tests/utils/tap/tap.c index a7ec3db2c..1ef417fed 100644 --- a/tests/utils/tap/tap.c +++ b/tests/utils/tap/tap.c @@ -5,6 +5,8 @@ * Copyright (C) 2017 Jérémie Galarneau */ +#include "../utils.h" +#include "common/compat/time.hpp" #include "tap.h" #include @@ -14,6 +16,7 @@ #include #include #include +#include static int no_plan = 0; static int skip_all = 0; @@ -25,6 +28,8 @@ static char *todo_msg = NULL; static const char *todo_msg_fixed = "libtap malloc issue"; static int todo = 0; static int test_died = 0; +static int time_tests = 1; +struct timespec last_time; /* Encapsulate the pthread code in a conditional. In the absence of libpthread the code does nothing */ @@ -141,6 +146,7 @@ unsigned int _gen_result( } printf("\n"); + _output_test_time(); if (!ok) { if (getenv("HARNESS_ACTIVE") != NULL) @@ -176,8 +182,18 @@ void _tap_init(void) in the same place relative to stderr output as it does with Test::Harness */ setbuf(stdout, 0); + + char *autotime_env = getenv("TAP_AUTOTIME"); + if (autotime_env != NULL) { + time_tests = atoi(autotime_env); + if (time_tests != 0) { + time_tests = 1; + } + } + run_once = 1; } + lttng_clock_gettime(CLOCK_MONOTONIC, &last_time); } /* @@ -319,6 +335,7 @@ int skip(unsigned int n, const char *fmt, ...) printf("ok %d # skip %s\n", test_count, skip_msg != NULL ? skip_msg : "libtap():malloc() failed"); + _output_test_time(); } free(skip_msg); @@ -328,6 +345,20 @@ int skip(unsigned int n, const char *fmt, ...) return 1; } +void _output_test_time(void) +{ + struct timespec new_time; + int64_t time_ns; + if (time_tests) { + lttng_clock_gettime(CLOCK_MONOTONIC, &new_time); + time_ns = elapsed_time_ns(&last_time, &new_time); + printf(" ---\n duration_ms: %ld.%ld\n ...\n", + time_ns / 1000000, + time_ns % 1000000); + } + lttng_clock_gettime(CLOCK_MONOTONIC, &last_time); +} + void todo_start(const char *fmt, ...) { va_list ap; diff --git a/tests/utils/tap/tap.h b/tests/utils/tap/tap.h index 5da691919..d4419181a 100644 --- a/tests/utils/tap/tap.h +++ b/tests/utils/tap/tap.h @@ -66,6 +66,8 @@ extern "C" { __attribute__((format(TAP_PRINTF_FORMAT, 5, 6))) unsigned int _gen_result(int, const char *, const char *, unsigned int, const char *, ...); +void _output_test_time(void); + int plan_no_plan(void); __attribute__((noreturn)) int plan_skip_all(const char *); int plan_tests(unsigned int); diff --git a/tests/utils/tap/tap.sh b/tests/utils/tap/tap.sh index 4b51106c0..993db27c8 100755 --- a/tests/utils/tap/tap.sh +++ b/tests/utils/tap/tap.sh @@ -14,8 +14,11 @@ _test_died=0 _expected_tests=0 _executed_tests=0 _failed_tests=0 +_auto_timing="${TAP_AUTOTIME:-1}" +_last_time='' TODO= - +TIME_SCRIPT="$(realpath -e -- "$(dirname "${BASH_SOURCE[0]}")")/clock" +print "${TIME_SCRIPT}" usage(){ cat <<'USAGE' @@ -52,6 +55,7 @@ TODO: OTHER: diag MSG + autotime 0|1 EXAMPLE: #!/bin/bash @@ -105,6 +109,7 @@ plan_no_plan(){ _plan_set=1 _no_plan=1 + _last_time=$("${TIME_SCRIPT}") return 0 } @@ -119,6 +124,7 @@ plan_skip_all(){ _skip_all=1 _plan_set=1 + _last_time=$("${TIME_SCRIPT}") _exit 0 return 0 @@ -133,6 +139,7 @@ plan_tests(){ _print_plan $tests _expected_tests=$tests _plan_set=1 + _last_time=$("${TIME_SCRIPT}") return $tests } @@ -195,6 +202,7 @@ ok(){ fi echo + _autotime if (( result != 0 )) ; then local file='tap-functions' local func= @@ -233,6 +241,7 @@ okx(){ diag "$line" done ok ${PIPESTATUS[0]} "$command" + _autotime } @@ -342,6 +351,7 @@ skip(){ for (( i=0 ; i<$n ; i++ )) ; do _executed_tests=$(( _executed_tests + 1 )) echo "ok $_executed_tests # skip: $reason" + _autotime done return 0 else @@ -349,6 +359,32 @@ skip(){ fi } +_autotime(){ + local new_time + local duration + + if [ "${_auto_timing}" -eq "1" ] ; then + new_time=$("${TIME_SCRIPT}") + duration=$(awk "BEGIN { printf(\"%f\n\", ($new_time - $_last_time)*1000) }") + echo " ---" + echo " duration_ms: ${duration}" + echo " ..." + fi + _last_time=$("${TIME_SCRIPT}") + return 0 +} + + +autotime(){ + local val=${1:?} + + if [[ "${val}" != "0" ]] ; then + _auto_timing=1 + else + _auto_timing=0; + fi + return 0 +} diag(){ local msg=${1:?} diff --git a/tests/utils/test_utils.py b/tests/utils/test_utils.py index ba9c2946e..8980cc8d1 100644 --- a/tests/utils/test_utils.py +++ b/tests/utils/test_utils.py @@ -10,6 +10,7 @@ import os import subprocess import shutil import sys +import time import tempfile # Import lttng bindings generated in the current tree @@ -22,6 +23,11 @@ sys.path.append(lttng_bindings_path) sys.path.append(lttng_bindings_libs_path) from lttng import * +_time_tests = True +if os.getenv("TAP_AUTOTIME", "1") == "" or os.getenv("TAP_AUTOTIME", "1") == "0": + _time_tests = False +_last_time = time.monotonic_ns() + BABELTRACE_BIN="babeltrace2" class SessionInfo: @@ -43,6 +49,15 @@ def bail(diag, session_info = None): shutil.rmtree(session_info.tmp_directory) exit(-1) +def print_automatic_test_timing(): + global _time_tests + global _last_time + if not _time_tests: + return + duration_ns = time.monotonic_ns() - _last_time + print(" ---\n duration_ms: {:02f}\n ...".format(duration_ns / 1_000_000)) + _last_time = time.monotonic_ns() + def print_test_result(result, number, description): result_string = None if result is True: @@ -52,9 +67,11 @@ def print_test_result(result, number, description): result_string += " {0} - {1}".format(number, description) print(result_string) + print_automatic_test_timing() def skip_test(number, description): print('ok {} # skip {}'.format(number, description)) + print_automatic_test_timing() def enable_ust_tracepoint_event(session_info, event_name): event = Event() diff --git a/tests/utils/utils.cpp b/tests/utils/utils.cpp index c95b46227..fbf0019cb 100644 --- a/tests/utils/utils.cpp +++ b/tests/utils/utils.cpp @@ -22,7 +22,7 @@ #include #include -static inline int64_t elapsed_time_ns(struct timespec *t1, struct timespec *t2) +int64_t elapsed_time_ns(struct timespec *t1, struct timespec *t2) { struct timespec delta; diff --git a/tests/utils/utils.h b/tests/utils/utils.h index 87b4918de..802743ec1 100644 --- a/tests/utils/utils.h +++ b/tests/utils/utils.h @@ -8,6 +8,7 @@ #ifndef TEST_UTILS_H #define TEST_UTILS_H +#include #include #if defined(__cplusplus) @@ -42,7 +43,7 @@ extern "C" { int usleep_safe(useconds_t usec); int create_file(const char *path); int wait_on_file(const char *path); - +int64_t elapsed_time_ns(struct timespec *t1, struct timespec *t2); #if defined(__cplusplus) } #endif -- 2.34.1