tests: Automatically time TAP tests
authorKienan Stewart <kstewart@efficios.com>
Fri, 25 Aug 2023 19:31:16 +0000 (15:31 -0400)
committerJérémie Galarneau <jeremie.galarneau@efficios.com>
Thu, 21 Dec 2023 21:38:35 +0000 (16:38 -0500)
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 <kstewart@efficios.com>
Signed-off-by: Jérémie Galarneau <jeremie.galarneau@efficios.com>
Change-Id: Iabc35fc00f14085ef035d4b4e19a2c30cd86d851

.gitignore
tests/utils/lttngtest/tap_generator.py
tests/utils/tap-driver.sh
tests/utils/tap/Makefile.am
tests/utils/tap/clock.cpp [new file with mode: 0644]
tests/utils/tap/tap.c
tests/utils/tap/tap.h
tests/utils/tap/tap.sh
tests/utils/test_utils.py
tests/utils/utils.cpp
tests/utils/utils.h

index ca36c537b4ec884ff2bccce2edff19e4cdee09c1..eb2873e011bc0baf5d1e927ba48a6b9ad223f923 100644 (file)
@@ -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
index 39c6bda903093c60222bdb8d3a7b3f067d3d7b43..f87c8c88ba5f8074b29b202cbbaeff1c84013b74 100644 (file)
@@ -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
index cbe2952210223ce6dc46f9d42da2cb2f60263d1b..1e61e1f2870746a8d3aa11f6903f7e8a624235a7 100755 (executable)
@@ -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)
 }
 
index f84d91c8ae331061358098a24b601881fd39ed47..a914b781313ec8c02f556b3fcc0104bfc3c83942 100644 (file)
@@ -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 (file)
index 0000000..5a99ddd
--- /dev/null
@@ -0,0 +1,18 @@
+/**
+ * Copyright (C) 2023 Kienan Stewart <kstewart@efficios.com>
+ *
+ * SPDX-License-Identifier: LGPL-2.1-only
+ */
+
+#include "common/time.hpp"
+
+#include <stdio.h>
+
+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;
+}
index a7ec3db2c4ada41c9d23aedb951711818f6e3ca7..1ef417fed34a70b4897918815c2c783db4840fd5 100644 (file)
@@ -5,6 +5,8 @@
  * Copyright (C) 2017 Jérémie Galarneau
  */
 
+#include "../utils.h"
+#include "common/compat/time.hpp"
 #include "tap.h"
 
 #include <assert.h>
@@ -14,6 +16,7 @@
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
+#include <time.h>
 
 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;
index 5da691919f08446fa14d9f58d392faf580fcad58..d4419181a64212521ea2481dc1740af67796df08 100644 (file)
@@ -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);
index 4b51106c013273aee268342734446f5c43f2aabe..993db27c8f121b763bbd3f1697770bbe65014d65 100755 (executable)
@@ -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:?}
index ba9c2946e7654cea703f74cd43b23a872ec662b9..8980cc8d13a3ebf7c0d785627049d80f810ca17c 100644 (file)
@@ -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()
index c95b4622709570c9f313085c4dedd5c74b59dfcf..fbf0019cb713f43d08ced60a39553a9e770dce50 100644 (file)
@@ -22,7 +22,7 @@
 #include <sys/types.h>
 #include <unistd.h>
 
-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;
 
index 87b4918def3a9960a230b4ace04ad71b56007128..802743ec1fd32fc3c6c5c420ac058c9181dc132c 100644 (file)
@@ -8,6 +8,7 @@
 #ifndef TEST_UTILS_H
 #define TEST_UTILS_H
 
+#include <sys/types.h>
 #include <unistd.h>
 
 #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
This page took 0.036445 seconds and 4 git commands to generate.