GNOME Bugzilla – Bug 700460
rewrite tests to not rely on precise timing of timeouts
Last modified: 2018-05-24 15:20:06 UTC
I saw this at least once: GLib:ERROR:../../../glib/tests/mainloop.c:494:test_recursive_child_sources: assertion failed (a == 9): (8 == 9) The test is "orange" though because it passed later without a source code change.
need to rewrite this (and as many other tests as possible) to not use timeouts
*** Bug 703060 has been marked as a duplicate of this bug. ***
from 703060, same basic issue: "GLib-GIO:ERROR:../../../gio/tests/socket.c:631:test_timed_wait: assertion failed (poll_duration < 112000): (126884 < 112000)" }
The mainloop test originated with: commit 1b01109377a4780431996d617643704351a27d8f Author: Matthias Clasen <mclasen@redhat.com> AuthorDate: Tue Nov 22 23:57:18 2011 -0500 Add some more mainloop tests Since then the specific assertions have been revised for this exact issue: commit 95f29687e14423ca541cac1c00137375b935168d Author: Martin Pitt <martinpitt@gnome.org> AuthorDate: Wed Jun 27 11:46:28 2012 +0200 /mainloop/timeouts test: Reduce race condition Now looking at this code...I'm not sure how to make this test as written work at all. The thing is, we may be delayed for an arbitrary amount of time, so for example a = b = c = 1. In practice we've seen a = 8 in the gnome-ostre eintegrationtest. I think the only assertions we can make of this form are "a < b". Matthias, do you agree?
Created attachment 248933 [details] [review] 0001-tests-mainloop-Fix-assertions-to-really-avoid-race-c.patch This was actually really easy to reproduce, just do: $ while ./mainloop; do true; done & $ pkill -SIGSTOP lt-mainloop (wait a few seconds) $ pkill -CONT lt-mainloop Without this patch, it aborts pretty quickly. With it, no race conditions.
Comment on attachment 248933 [details] [review] 0001-tests-mainloop-Fix-assertions-to-really-avoid-race-c.patch I think we can also assert g_assert_cmpint (a, >=, b); g_assert_cmpint (b, >=, c); ? But since this test is supposed to actually be testing that timeouts work (as opposed to using timeouts to test that something else works), maybe we could also have non-fatal warnings when we get unexpected results? if (a != 10 || b != 4 || c != 3) g_test_message ("Unexpected timeout results (a = %d, b = %d, c = %d); this is a bug if it occurs reliably when running on a fast, idle machine", a, b, c); That way people running the tests by hand still might notice (other than the fact that g_test_message() is essentially a black hole...)
(In reply to comment #6) > (From update of attachment 248933 [details] [review]) > I think we can also assert > > g_assert_cmpint (a, >=, b); > g_assert_cmpint (b, >=, c); Yes, that is a lot nicer looking and a stronger assertion. Fixed. > if (a != 10 || b != 4 || c != 3) > g_test_message ("Unexpected timeout results (a = %d, b = %d, c = %d); this > is a bug if it occurs reliably when running on a fast, idle machine", a, b, c); Eh. The thing is that it really is a normal condition. In multiple ways. Hopefully "most" real-world deployments using GLib now are not actually idle. If the computer's on, it should be doing work or scheduled to do some soon; otherwise you're just burning power. And personally I tend to use "gnome-desktop-testing-runner -p 0" a lot - running the tests in parallel especially on a fast machine *really* cuts down on the test latency.
Created attachment 249005 [details] [review] 0001-tests-mainloop-Fix-assertions-to-really-avoid-race-c.patch
Review of attachment 249005 [details] [review]: sure, if this works
Created attachment 249749 [details] [review] Fix races in tests/unix
Comment on attachment 249749 [details] [review] Fix races in tests/unix >...and rewrite the test into the newly idiomatic "look ma no GMainLoop!" >style. The reason this style is better is because we don't want: > >on_timeout () >{ > g_error ("timed out!"); >} (That's orthogonal to whether you use a GMainLoop or not; you could just do sig_timeout = TRUE; g_main_loop_quit (loop); rather than g_error() immediately.) >Furthermore the sighup-nested test had a subtle race condition: >Because we're running a nested main context, it's possible >that the GLib worker thread will grab the outer main context and >run our callback first before we process the inner loop. Fix >this by creating separate conditions for the nested and outer >loops. I don't see how this is possible; first, I'm not sure what you mean by "will grab the outer main context"; the worker thread does not do any context grabbing that I can see. And even if it did try to acquire the default GMainContext, it should fail, because nested_idle() is running from inside that context, and so the context must already be acquired by the main thread.
(In reply to comment #11) > I don't see how this is possible; Right, OK, it's a different bug than what I thought. The *previous* test, sighup_add_remove, adds a SIGHUP handler and removes it, then sends SIGHUP. This leaves a pending SIGHUP state. When the sighup_nested test then iterates the context, we still have that pending state, which terminates the loop early. My patch "fixed" this because I changed the assertion to be that we had received two signals. This gets to an interesting question: What are the expected semantics of adding and then removing a Unix signal watch? Should we revert to the default behavior? Probably - if you add a SIGTERM handler, then for some reason remove it, you'd expect SIGTERM to still terminate the process.
(In reply to comment #12) > This gets to an interesting question: What are the expected semantics of adding > and then removing a Unix signal watch? Should we revert to the default > behavior? Probably - if you add a SIGTERM handler, then for some reason remove > it, you'd expect SIGTERM to still terminate the process. Yeah... adding and removing a signal watch should be like setting and removing a signal handler I guess.
Broke out a patch for that in: https://bugzilla.gnome.org/show_bug.cgi?id=704699
Created attachment 249830 [details] [review] don't immediately error on timeout
Comment on attachment 249830 [details] [review] don't immediately error on timeout sure
Comment on attachment 249830 [details] [review] don't immediately error on timeout Ok, still to go is at least the rest of glib/tests/mainloop.c.
Created attachment 249983 [details] [review] 0001-tests-mainloop-Relax-conditions-for-non-idle-systems.patch
Ok, one thing we need to figure out is how to handle "should not be reached" timeouts, like the one in test_swapping_child_sources(). At the moment it's pretty easy to make this test fail since the timeout is a mere 50ms. We could define some "reasonable test timeout" like 10 seconds. Or alternatively, we could ditch these random timeouts, and rely on the test harness to have a timeout. Yet another alternative would be doing something a bit more clever and emphasizing time during which the process has been scheduled for these test timeouts. g_process_timeout_new() ? We'd still need an outer non-scheduling timeout, but a way to schedule a timeout that only counts time spent inside its GMainContext would be pretty interesting potentially.
Created attachment 250043 [details] [review] mainloop: redo child source tests to not use timeouts The timeout-based tests could fail on slow or heavily-loaded machines. Change them to use a counter-based "timeout" source rather than a time-based one, so they no longer depend on wall time. ==== How about this instead? (which is more or less like your "process timeout" idea)
Review of attachment 250043 [details] [review]: This is interesting; but at a high level, we should still be testing timeout sources I think; we just have to have weaker assertions for them. You're not modifying the assertions I already weakened, but with this counter source you could create new tests with tighter assertions. ::: glib/tests/mainloop.c @@ +360,3 @@ + +static gint counter; +static gint64 last_counter_update; Were we to make this a bit more robust, this data should be looked up via GHashTable<GMainContext,CounterSourceData> or something. Secondly, you are not resetting the counter variable between tests, but we need to do that, right?
(In reply to comment #21) > Review of attachment 250043 [details] [review]: > > This is interesting; but at a high level, we should still be testing timeout > sources I think Sure, but we still have test_timeouts() in mainloop.c, plus all of timeout.c. I only changed the child source tests, which were using timeouts to control the ordering of events, but don't actually care about *time* per se. > +static gint counter; > +static gint64 last_counter_update; > > Were we to make this a bit more robust, this data should be looked up via > GHashTable<GMainContext,CounterSourceData> or something. As originally written, the tests assumed that "time" keeps passing for the sources in the outer GMainContext even when there's an inner GMainContext running and keeping them from being dispatched. Making the counter be per-GMainContext and/or per-source would break that, requiring more rewriting of the tests. (Technically, counter should probably be per-thread, but that wasn't relevant for these tests, so I didn't bother.) > Secondly, you are not resetting the counter variable between tests, but we need > to do that, right? No, when you create a new counter source, it sets its timeout relative to the current value of counter.
Review of attachment 250043 [details] [review]: That all makes sense; looks good to me then!
Comment on attachment 250043 [details] [review] mainloop: redo child source tests to not use timeouts Attachment 250043 [details] pushed as 2127654 - mainloop: redo child source tests to not use timeouts still got at least gio/tests/socket
I assume this is fixed then?
(In reply to comment #25) > I assume this is fixed then? no: (In reply to comment #24) > still got at least gio/tests/socket
*** Bug 755741 has been marked as a duplicate of this bug. ***
Created attachment 312310 [details] [review] Avoid spurious timing failures in tests Slow/heavily-loaded build machines tend to have problems with tests that involve precise timing. So if the g_socket_condition_timed_wait() or g_async_queue_timed_pop() tests fail, just mark the test skipped rather than failed, with a message explaining that it may or may not indicate a bug.
Will we ever debug "nondeterministic skips" though? Hmm. On Linux, we could look at /proc/self/status: * voluntary_context_switches, nonvoluntary_context_switches: Number of voluntary and involuntary context switches (since Linux 2.6.23). We could say if number is unchanged, assert stronger bounds on the monotonic clock, e.g. that no more than 1 monotonic second elapsed?
Review of attachment 312310 [details] [review]: ::: glib/tests/asyncqueue.c @@ +237,3 @@ + g_test_skip (msg); + g_free (msg); + } This looks like it could be extracted into a helper function?
Created attachment 314930 [details] [review] Avoid spurious timing failures in tests ==== (In reply to Colin Walters from comment #30) > This looks like it could be extracted into a helper function? OK, the new version adds "g_assert_timing()". It seemed to make sense to make it a public function, since other packages have timing-related tests too...
-- GitLab Migration Automatic Message -- This bug has been migrated to GNOME's GitLab instance and has been closed from further activity. You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.gnome.org/GNOME/glib/issues/703.