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)
commit2a69bf1437eb7e81979a1410b1a66a960b52caeb
treedb9df5d2aaa12d456e4ee01678cb04cec76090ba
parente73b293111eacc3c0f6eca0009ac3afa51ea85f1
tests: Automatically time TAP tests

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
This page took 0.026224 seconds and 4 git commands to generate.