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
/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/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/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
/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
from typing import Iterator, Optional
from typing import Iterator, Optional
self._last_test_case_id = 0 # type: int
self._printed_plan = False # type: bool
self._has_failure = False # type: bool
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:
def __del__(self):
if self.remaining_test_cases > 0:
def test(self, result, description):
# type: (bool, str) -> None
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")
if self._last_test_case_id == self._total_test_count:
raise InvalidTestPlan("Executing too many tests")
description=description,
)
)
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
def ok(self, description):
# type: (str) -> None
+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.
# :; 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.
+ # 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" \
echo $?
) | LC_ALL=C ${AM_TAP_AWK-awk} \
-v me="$me" \
-v ignore_exit="$ignore_exit" \
-v comments="$comments" \
-v diag_string="$diag_string" \
-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/.
'
# TODO: the usages of "cat >&3" below could be optimized when using
# GNU awk, and/on on systems that supports /dev/fd/.
-function gettime_ns( r, cmd)
+ if (time_script | getline r) {
return sprintf("%f", r)
}
return sprintf("%f", r)
}
# SPDX-License-Identifier: GPL-2.0-only
# 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
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
dist_noinst_SCRIPTS = tap.sh
EXTRA_DIST = tap.sh
--- /dev/null
+/**
+ * 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;
+}
* Copyright (C) 2017 Jérémie Galarneau
*/
* Copyright (C) 2017 Jérémie Galarneau
*/
+#include "../utils.h"
+#include "common/compat/time.hpp"
#include "tap.h"
#include <assert.h>
#include "tap.h"
#include <assert.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
static int no_plan = 0;
static int skip_all = 0;
static int no_plan = 0;
static int skip_all = 0;
static const char *todo_msg_fixed = "libtap malloc issue";
static int todo = 0;
static int test_died = 0;
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 */
/* Encapsulate the pthread code in a conditional. In the absence of
libpthread the code does nothing */
if (!ok) {
if (getenv("HARNESS_ACTIVE") != NULL)
if (!ok) {
if (getenv("HARNESS_ACTIVE") != NULL)
in the same place relative to stderr output as it does
with Test::Harness */
setbuf(stdout, 0);
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;
+ }
+ }
+
+ lttng_clock_gettime(CLOCK_MONOTONIC, &last_time);
printf("ok %d # skip %s\n",
test_count,
skip_msg != NULL ? skip_msg : "libtap():malloc() failed");
printf("ok %d # skip %s\n",
test_count,
skip_msg != NULL ? skip_msg : "libtap():malloc() failed");
+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;
void todo_start(const char *fmt, ...)
{
va_list ap;
__attribute__((format(TAP_PRINTF_FORMAT, 5, 6))) unsigned int
_gen_result(int, const char *, const char *, unsigned int, const char *, ...);
__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);
int plan_no_plan(void);
__attribute__((noreturn)) int plan_skip_all(const char *);
int plan_tests(unsigned int);
_expected_tests=0
_executed_tests=0
_failed_tests=0
_expected_tests=0
_executed_tests=0
_failed_tests=0
+_auto_timing="${TAP_AUTOTIME:-1}"
+_last_time=''
+TIME_SCRIPT="$(realpath -e -- "$(dirname "${BASH_SOURCE[0]}")")/clock"
+print "${TIME_SCRIPT}"
+ _last_time=$("${TIME_SCRIPT}")
+ _last_time=$("${TIME_SCRIPT}")
_print_plan $tests
_expected_tests=$tests
_plan_set=1
_print_plan $tests
_expected_tests=$tests
_plan_set=1
+ _last_time=$("${TIME_SCRIPT}")
if (( result != 0 )) ; then
local file='tap-functions'
local func=
if (( result != 0 )) ; then
local file='tap-functions'
local func=
diag "$line"
done
ok ${PIPESTATUS[0]} "$command"
diag "$line"
done
ok ${PIPESTATUS[0]} "$command"
for (( i=0 ; i<$n ; i++ )) ; do
_executed_tests=$(( _executed_tests + 1 ))
echo "ok $_executed_tests # skip: $reason"
for (( i=0 ; i<$n ; i++ )) ; do
_executed_tests=$(( _executed_tests + 1 ))
echo "ok $_executed_tests # skip: $reason"
+_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
+}
import subprocess
import shutil
import sys
import subprocess
import shutil
import sys
import tempfile
# Import lttng bindings generated in the current tree
import tempfile
# Import lttng bindings generated in the current tree
sys.path.append(lttng_bindings_libs_path)
from lttng import *
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:
BABELTRACE_BIN="babeltrace2"
class SessionInfo:
shutil.rmtree(session_info.tmp_directory)
exit(-1)
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:
def print_test_result(result, number, description):
result_string = None
if result is True:
result_string += " {0} - {1}".format(number, description)
print(result_string)
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))
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()
def enable_ust_tracepoint_event(session_info, event_name):
event = Event()
#include <sys/types.h>
#include <unistd.h>
#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)
#ifndef TEST_UTILS_H
#define TEST_UTILS_H
#ifndef TEST_UTILS_H
#define TEST_UTILS_H
#include <unistd.h>
#if defined(__cplusplus)
#include <unistd.h>
#if defined(__cplusplus)
int usleep_safe(useconds_t usec);
int create_file(const char *path);
int wait_on_file(const char *path);
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
#if defined(__cplusplus)
}
#endif