Test interactions in pyqt test suite

[ievacerny]

While working on unittest runner I discovered that the pyqt test suite is being much slower and 4 timer tests are failing due to time-outs (see below for test errors). This does not happen with nose or haas test runners because they run tests in pyface/tests after pyface/timer/tests and pyface/ui/qt. The change in behaviour based on the order of the tests suggests test interactions.

I have checked for QObject leakage - there is some, but it doesn't seem to be the cause of the slowdown. The slowdown seems to be related to the event loop -- the problem can be "fixed" by skipping tests in test_gui_application and tests that use ModalDialogTester, or by running them at the end of the pyqt test suite.

Note: the slowdown also doesn't happen if the test suite is run in the foreground.

Test Errors

``` ====================================================================== ERROR: test_interval (pyface.timer.tests.test_timer.TestCallbackTimer) ---------------------------------------------------------------------- Traceback (most recent call last): File "/Users/icernyte/Documents/repos/pyface/pyface/timer/tests/test_timer.py", line 292, in test_interval lambda: not timer.active File "/Users/icernyte/Documents/repos/pyface/pyface/ui/qt4/util/event_loop_helper.py", line 133, in event_loop_until_condition "Timed out waiting for condition" pyface.ui.qt4.util.event_loop_helper.ConditionTimeoutError: Timed out waiting for condition ====================================================================== ERROR: test_repeat (pyface.timer.tests.test_timer.TestCallbackTimer) ---------------------------------------------------------------------- Traceback (most recent call last): File "/Users/icernyte/Documents/repos/pyface/pyface/timer/tests/test_timer.py", line 276, in test_repeat lambda: not timer.active File "/Users/icernyte/Documents/repos/pyface/pyface/ui/qt4/util/event_loop_helper.py", line 133, in event_loop_until_condition "Timed out waiting for condition" pyface.ui.qt4.util.event_loop_helper.ConditionTimeoutError: Timed out waiting for condition ====================================================================== ERROR: test_interval (pyface.timer.tests.test_timer.TestEventTimer) ---------------------------------------------------------------------- Traceback (most recent call last): File "/Users/icernyte/Documents/repos/pyface/pyface/timer/tests/test_timer.py", line 139, in test_interval lambda: not timer.active File "/Users/icernyte/Documents/repos/pyface/pyface/ui/qt4/util/event_loop_helper.py", line 133, in event_loop_until_condition "Timed out waiting for condition" pyface.ui.qt4.util.event_loop_helper.ConditionTimeoutError: Timed out waiting for condition ====================================================================== ERROR: test_repeat (pyface.timer.tests.test_timer.TestEventTimer) ---------------------------------------------------------------------- Traceback (most recent call last): File "/Users/icernyte/Documents/repos/pyface/pyface/timer/tests/test_timer.py", line 124, in test_repeat lambda: not timer.active File "/Users/icernyte/Documents/repos/pyface/pyface/ui/qt4/util/event_loop_helper.py", line 133, in event_loop_until_condition "Timed out waiting for condition" pyface.ui.qt4.util.event_loop_helper.ConditionTimeoutError: Timed out waiting for condition ---------------------------------------------------------------------- Ran 574 tests in 368.345s FAILED (errors=4, skipped=19) Command '['/Users/icernyte/.edm/envs/dev-general/bin/edm', 'run', '-e', 'pyface-test-3.6-pyqt', '--', 'coverage', 'run', '-p', '-m', 'unittest', 'discover', '-v', 'pyface']' returned non-zero exit status 1. ```

[mdickinson]

Can we pare this down to an example pair of individual unit tests: TestA and TestB, such that TestB is taken from the Pyface timer tests, and TestB fails with timeout if run after TestA, but not if run before TestA? That would provide the basis for further investigation into exactly which piece of global state has changed that causes TestB to succeed with one ordering and fail with the opposite ordering.

[ievacerny]

It doesn't seem to be just one specific test. I think it's a lot of tests doing something to the event loop and when the critical mass is reached, the timer tests start failing.

I managed to replicate this using 2 specific tests: pyface.tests.test_confirmation_dialog.TestConfirmationDialog.test_yes and pyface.timer.tests.test_timer.TestCallbackTimer.test_repeat. To cause a failure of test_repeat test_yes has to be run ~350 times before it (in one suite run). Slow down without failure starts to happen at around ~300 test_yes repetitions.

[mdickinson]

Probably a stupid question, but is there a growth in the number of threads being used over the course of the test run (e.g., as reported by top), or does that remain stable?

[ievacerny]

Probably a stupid question, but is there a growth in the number of threads being used over the course of the test run (e.g., as reported by top), or does that remain stable?

It's stable.

[mdickinson]

I recently saw similar behaviour with the traits-futures test suite. As with this issue, the problem doesn't occur if the tests are run in the foreground, and switching back to the test-run process from a different one causes the slow test run to speed up again.

This Qt issue looks related: https://bugreports.qt.io/browse/QTBUG-63832

For traits-futures, I managed to work around the issue by avoiding the GUITestAssistant's use of polling with a QTimer: enthought/traits-futures#153.