Skip to content

gtestutils: print timing information per test case in TAP output

Daniel P. Berrange requested to merge dberrange/glib:test-timing into main

This changes the TAP output to make it display the timing for any test case taking longer than 0.5 seconds:

      $ ./build/glib/tests/unix
      TAP version 13
      # random seed: R02S690dc3c7a04866e4890501eedc7f8eef
      1..13
      # Start of glib-unix tests
      ok 1 /glib-unix/pipe
      # /glib-unix/pipe-stdio-overwrite summary: Test that g_unix_open_pipe() will use the first available FD, even if it?s stdin/stdout/stderr
      # Bug Reference: https://gitlab.gnome.org/GNOME/glib/-/issues/2795
      ok 2 /glib-unix/pipe-stdio-overwrite
      ok 3 /glib-unix/error
      ok 4 /glib-unix/nonblocking
      ok 5 /glib-unix/sighup
      # slow test /glib-unix/sighup executed in 0.50 secs
      ok 6 /glib-unix/sigterm
      # slow test /glib-unix/sigterm executed in 0.50 secs
      ok 7 /glib-unix/sighup_again
      # slow test /glib-unix/sighup_again executed in 0.50 secs
      ok 8 /glib-unix/sighup_add_remove
      ok 9 /glib-unix/sighup_nested
      ok 10 /glib-unix/callback_after_signal
      # slow test /glib-unix/callback_after_signal took 2.00 secs
      ok 11 /glib-unix/child-wait
      # Start of get-passwd-entry tests
      # /glib-unix/get-passwd-entry/root summary: Tests that g_unix_get_passwd_entry() works for a known-existing username.
      ok 12 /glib-unix/get-passwd-entry/root
      # /glib-unix/get-passwd-entry/nonexistent summary: Tests that g_unix_get_passwd_entry() returns an error for a nonexistent username.
      ok 13 /glib-unix/get-passwd-entry/nonexistent
      # End of get-passwd-entry tests
      # End of glib-unix tests

My motivation for this comes from (painful) efforts debugging tests in QEMU, especially in relation to non-interactive, automated CI logs. While it is possible to run tests individually using '-p /test/case/path' and time them that way, this not especially convenient, particularly when it comes to analysing CI pipelines results. A local execution platform is entirely different hardware and so frequently won't accurately reproduce problems we see time & again in CI.

For example, we periodically hit 1hr timeouts in GitLab CI pipelines while running tests and diagnosing why this sometimes happens is hard. One possibility is that some tests occasionally & non-deterministically hit edge cases making them run slowly, another possibility is that the CI environment VM is running everything slowly. With per test case timing, we can more easily identify if a specific test case is exhibiting problems, or the entire set is tests is slow due to VM resource starvation.

Glib is already timing every test case, but AFAICT, that info is discarded. This change just tweaks the TAP output to present the info already being collected.

As a practical usage example, the meson log can be queried to find slow tests project-wide:

      $ grep 'slow test' build/meson-logs/testlog.txt | sort -n -k 7 -r | head
      # slow test /threadpool/basics executed in 36.04 secs
      # slow test /gobject/refcount/properties-3 executed in 30.00 secs
      # slow test /gio/io-basics executed in 12.54 secs
      # slow test /timeout/rounding executed in 10.60 secs
      # slow test /GObject/threaded-weak-ref executed in 10.42 secs
      # slow test /thread/rerun-all executed in 9.84 secs
      # slow test /gobject/refcount/object-advanced executed in 5.46 secs
      # slow test /thread/static-rw-lock executed in 5.00 secs
      # slow test /gobject/refcount/signals executed in 5.00 secs
      # slow test /gobject/refcount/signals executed in 5.00 secs
Edited by Daniel P. Berrange

Merge request reports