luc14n0/glib
1
0
Fork 0
mirror of https://gitlab.gnome.org/GNOME/glib.git synced 2024-11-09 19:06:15 +01:00
Code Issues Packages Projects Releases Wiki Activity

gtestutils: print execution time after every test

Browse Source 
Displaying the execution time will aid developers in understanding which
test cases are responsible for slow execution times. The test code is
already measuring the execution time for every test case, but is not
reporting that data anywhere accessible to developers running the tests.

The new code will print a TAP comment:

  # slow test /the/test/path executed in NN.NN secs

for any test taking longer than 0.5 seconds to run.

Example new output format:

  $ ./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

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

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
This commit is contained in:
Daniel P. Berrangé 2023-05-03 15:20:21 +01:00 committed by Philip Withnall
parent b6ce20329a
commit 29311d4309
1 changed files with 12 additions and 0 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
glib/gtestutils.c
View File

@ -1097,6 +1097,7 @@ g_test_log (GTestLogType lbit,
guint8 *dbuffer;
guint32 dbufferlen;
unsigned subtest_level;
gdouble timing;
if (g_once_init_enter (&g_default_print_func))
{
@ -1154,6 +1155,7 @@ g_test_log (GTestLogType lbit,
break;
case G_TEST_LOG_STOP_CASE:
result = largs[G_TEST_CASE_LARGS_RESULT];
timing = largs[G_TEST_CASE_LARGS_EXECUTION_TIME];
fail = result == G_TEST_RUN_FAILURE;
if (test_tap_log)
{
@ -1184,6 +1186,16 @@ g_test_log (GTestLogType lbit,
g_string_append_c (tap_output, '\n');
g_default_print_func (tap_output->str);
g_string_free (g_steal_pointer (&tap_output), TRUE);
/* Print msg for any slow tests, where 'slow' means >= 0.5 secs */
if (timing > 0.5)
{
tap_output = g_string_new ("# ");
g_string_append_printf (tap_output, "slow test %s executed in %0.2lf secs\n",
string1, timing);
g_default_print_func (tap_output->str);
g_string_free (g_steal_pointer (&tap_output), TRUE);
}
}
else if (g_test_verbose ())
g_print ("GTest: result: %s\n", g_test_result_names[result]);