From c1fecf9c3bfd9ab9fc4fe1b089b05e5ea59a51d3 Mon Sep 17 00:00:00 2001 From: herr kaste Date: Wed, 28 Nov 2018 15:23:55 +0100 Subject: [PATCH 1/9] Deterministic timing for DeferrableTestCase Sublime's worker thread is a task queue. If you put tasks on it, they will run *ordered*. We can use this to make the `yield` timing deterministic. If we just `yield` (without an argument) we enqueue a task to be run ASAP. That means it will wait for tasks in the queue and then yield back to the test code. E.g. from the test we invoke the unit-under-test which in turn puts task (A) and (B) on the worker. We then `yield` which puts itself as (C) on the queue and waits for it. Sublime will now run (A), (B), and finally (C) ordered. The test runner now yields control back to the test. If (A) in turn enqueued a task (D) on the queue, it will not have run yet, and in fact will not run at all if we not `yield` again. See the test included here. Using this, I could bring down the execution time of the test in https://github.com/divmain/GitSavvy/pull/1056 from ~7.7s to 2.7s. I could replace all `yield ` expressions with single or double `yield`s, making the test more reasonable. Bc I know that a command e.g. 'hops' two times, I know exactly that I have to `yield` two times. This comes with the big caveat that coverage doesn't work on the worker thread. This is already true right now, see https://github.com/divmain/GitSavvy/pull/1056#issuecomment-442384812 and a big annoyance for writing functional tests. E.g. as soon as we just issue a command which itself is implemented to run 'async' (t.i. on the worker thread) and then just `yield ` to wait for it, the code under test will not be marked as 'covered'. --- tests/test_deferred_timing.py | 61 ++++++++++++++++++++++++++++++++++ unittesting/core/st3/runner.py | 8 ++--- 2 files changed, 65 insertions(+), 4 deletions(-) create mode 100644 tests/test_deferred_timing.py diff --git a/tests/test_deferred_timing.py b/tests/test_deferred_timing.py new file mode 100644 index 00000000..b5bbaef0 --- /dev/null +++ b/tests/test_deferred_timing.py @@ -0,0 +1,61 @@ +from functools import partial +import time + +import sublime + +from unittesting import DeferrableTestCase + + +def run_in_worker(fn, *args, **kwargs): + sublime.set_timeout_async(partial(fn, *args, **kwargs)) + + +class TestTimingInDeferredTestCase(DeferrableTestCase): + + def test_a(self): + messages = [] + + def work(message, worktime=None): + messages.append(message) + # simulate that a task might take some time + # this will not yield back but block + if worktime: + time.sleep(worktime) + + def uut(): + run_in_worker(work, 1, 0.5) # add task (A) + run_in_worker(work, 2) # add task (B) + + + uut() # after that task queue has: (A)..(B) + yield # add task (C) and wait for (C) + expected = [1, 2] + self.assertEqual(messages, expected) + + def test_b(self): + messages = [] + + def work(message, worktime=None): + messages.append(message) + if worktime: + time.sleep(worktime) + + def sub_task(): + run_in_worker(work, 2, 0.5) # add task (D) + + def uut(): + run_in_worker(work, 1, 0.5) # add task (A) + run_in_worker(sub_task) # add task (B) + + uut() + # task queue now: (A)..(B) + + yield # add task (C) and wait for (C) + # (A) runs, (B) runs and adds task (D), (C) resolves + expected = [1] + self.assertEqual(messages, expected) + # task queue now: (D) + yield # add task (E) and wait for it + # (D) runs and (E) resolves + expected = [1, 2] + self.assertEqual(messages, expected) diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index 89623f86..e92b0fcd 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -5,7 +5,7 @@ def defer(delay, callback, *args, **kwargs): - sublime.set_timeout(lambda: callback(*args, **kwargs), delay) + sublime.set_timeout_async(lambda: callback(*args, **kwargs), delay) class DeferringTextTestRunner(TextTestRunner): @@ -40,7 +40,7 @@ def _start_testing(): startTestRun() try: deferred = test(result) - defer(10, _continue_testing, deferred) + _continue_testing(deferred) except Exception as e: _handle_error(e) @@ -57,7 +57,7 @@ def _continue_testing(deferred): elif isinstance(condition, int): defer(condition, _continue_testing, deferred) else: - defer(10, _continue_testing, deferred) + defer(0, _continue_testing, deferred) except StopIteration: _stop_testing() @@ -132,4 +132,4 @@ def _stop_testing(): else: self.stream.write("\n") - sublime.set_timeout(_start_testing, 10) + _start_testing() From 95a993a1e2a6ecd0ab623a6d8637f5686042ad9b Mon Sep 17 00:00:00 2001 From: herr kaste Date: Thu, 29 Nov 2018 14:06:46 +0100 Subject: [PATCH 2/9] Further reduce waiting time --- unittesting/core/st3/runner.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index e92b0fcd..117e75ee 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -49,10 +49,10 @@ def _continue_testing(deferred): try: condition = next(deferred) if callable(condition): - defer(100, _wait_condition, deferred, condition) + defer(0, _wait_condition, deferred, condition) elif isinstance(condition, dict) and "condition" in condition and \ callable(condition["condition"]): - period = condition.get("period", 100) + period = condition.get("period", 5) defer(period, _wait_condition, deferred, **condition) elif isinstance(condition, int): defer(condition, _continue_testing, deferred) @@ -66,15 +66,15 @@ def _continue_testing(deferred): except Exception as e: _handle_error(e) - def _wait_condition(deferred, condition, period=100, timeout=10000, start_time=None): + def _wait_condition(deferred, condition, period=5, timeout=10000, start_time=None): if start_time is None: start_time = time.time() if condition(): - defer(10, _continue_testing, deferred) + _continue_testing(deferred) elif (time.time() - start_time) * 1000 >= timeout: self.stream.writeln("Condition timeout, continue anyway.") - defer(10, _continue_testing, deferred) + _continue_testing(deferred) else: defer(period, _wait_condition, deferred, condition, period, timeout, start_time) From bf6640dde507ab86f44a28a966a8a471ae963b48 Mon Sep 17 00:00:00 2001 From: herr kaste Date: Thu, 29 Nov 2018 14:08:01 +0100 Subject: [PATCH 3/9] Use `functools.partial` for safety and performance --- unittesting/core/st3/runner.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index 117e75ee..75dd282c 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -1,3 +1,4 @@ +from functools import partial import time from unittest.runner import TextTestRunner, registerResult import warnings @@ -5,12 +6,16 @@ def defer(delay, callback, *args, **kwargs): - sublime.set_timeout_async(lambda: callback(*args, **kwargs), delay) + sublime.set_timeout_async(partial(callback, *args, **kwargs), delay) class DeferringTextTestRunner(TextTestRunner): """This test runner runs tests in deferred slices.""" + # How can this be user configurable? + # controlled_timing = False + controlled_timing = True + def run(self, test): """Run the given test case or test suite.""" self.finished = False From 63b08cce81e04a6d11920c99af6e40e3c0613802 Mon Sep 17 00:00:00 2001 From: herr kaste Date: Thu, 29 Nov 2018 14:35:42 +0100 Subject: [PATCH 4/9] Swap `set_timeout_async` to do `set_timeout` In the first series of commits we tried to run all `yield` blocks, and by that a lot of the code under test, on the worker thread. This gives us more predictable timing bc a developer can count how many times their code 'hops' and then yield that many times. Generally, the FIFO principle is also true for the main thread. However, choosing the main thread is a bad option. (a) Usually the code under tests defers some work to the worker thread, and we really want to await that work. (b) The main thread runs faster. We choosed the slower thread bc when the worker yields a task, the main thread is usually done. There is one major caveat when we run on the worker thread t.i. coverage doesn't work anymore. This commit introduces a switch which will *globally* for the time of the tests swap `set_timeout_async` with `set_timeout`. By doing that (a) everything runs super fast, (b) every scheduled work/task runs on one thread, the main thread, so the FIFO principle holds and ensures deterministic timing, (c) all code under test gets coverage. This comes with one known caveat: Sublime puts '_async' events on the worker thread on its own, t.i. it doesn't use the patched API. For example, you cannot await such an event by just `yield`ing. You have to use `yield ` or `yield ` as before. --- unittesting/core/st3/runner.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index 75dd282c..d5472642 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -24,8 +24,12 @@ def run(self, test): result.failfast = self.failfast result.buffer = self.buffer startTime = time.time() + original_set_timeout_async = sublime.set_timeout_async def _start_testing(): + if self.controlled_timing: + sublime.set_timeout_async = sublime.set_timeout + with warnings.catch_warnings(): if self.warnings: # if self.warnings is set, use it to filter all the warnings @@ -91,6 +95,9 @@ def _handle_error(e): raise e def _stop_testing(): + if self.controlled_timing: + sublime.set_timeout_async = original_set_timeout_async + with warnings.catch_warnings(): stopTestRun = getattr(result, 'stopTestRun', None) if stopTestRun is not None: From 56130621a8d1cac209b53243bc6d5004d81b3d0d Mon Sep 17 00:00:00 2001 From: herr kaste Date: Sat, 1 Dec 2018 19:41:34 +0100 Subject: [PATCH 5/9] Fix lint errors --- tests/test_deferred_timing.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/tests/test_deferred_timing.py b/tests/test_deferred_timing.py index b5bbaef0..5562de48 100644 --- a/tests/test_deferred_timing.py +++ b/tests/test_deferred_timing.py @@ -26,7 +26,6 @@ def uut(): run_in_worker(work, 1, 0.5) # add task (A) run_in_worker(work, 2) # add task (B) - uut() # after that task queue has: (A)..(B) yield # add task (C) and wait for (C) expected = [1, 2] @@ -51,11 +50,11 @@ def uut(): # task queue now: (A)..(B) yield # add task (C) and wait for (C) - # (A) runs, (B) runs and adds task (D), (C) resolves + # (A) runs, (B) runs and adds task (D), (C) resolves expected = [1] self.assertEqual(messages, expected) # task queue now: (D) yield # add task (E) and wait for it - # (D) runs and (E) resolves + # (D) runs and (E) resolves expected = [1, 2] self.assertEqual(messages, expected) From d80ba2d83e25a00f29f9ea7d963ee765a93e9881 Mon Sep 17 00:00:00 2001 From: herr kaste Date: Wed, 5 Dec 2018 17:04:06 +0100 Subject: [PATCH 6/9] Remove temporary `controlled_timing` setting --- unittesting/core/st3/runner.py | 11 ----------- 1 file changed, 11 deletions(-) diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index d5472642..707a2898 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -12,10 +12,6 @@ def defer(delay, callback, *args, **kwargs): class DeferringTextTestRunner(TextTestRunner): """This test runner runs tests in deferred slices.""" - # How can this be user configurable? - # controlled_timing = False - controlled_timing = True - def run(self, test): """Run the given test case or test suite.""" self.finished = False @@ -24,12 +20,8 @@ def run(self, test): result.failfast = self.failfast result.buffer = self.buffer startTime = time.time() - original_set_timeout_async = sublime.set_timeout_async def _start_testing(): - if self.controlled_timing: - sublime.set_timeout_async = sublime.set_timeout - with warnings.catch_warnings(): if self.warnings: # if self.warnings is set, use it to filter all the warnings @@ -95,9 +87,6 @@ def _handle_error(e): raise e def _stop_testing(): - if self.controlled_timing: - sublime.set_timeout_async = original_set_timeout_async - with warnings.catch_warnings(): stopTestRun = getattr(result, 'stopTestRun', None) if stopTestRun is not None: From 38795129473179d36245e614ae3c057035b84078 Mon Sep 17 00:00:00 2001 From: herr kaste Date: Wed, 5 Dec 2018 17:04:30 +0100 Subject: [PATCH 7/9] Switch back to running on the main thread --- unittesting/core/st3/runner.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index 707a2898..622073e3 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -6,7 +6,8 @@ def defer(delay, callback, *args, **kwargs): - sublime.set_timeout_async(partial(callback, *args, **kwargs), delay) + sublime.set_timeout(partial(callback, *args, **kwargs), delay) + class DeferringTextTestRunner(TextTestRunner): From fa0df47a6101b19b7948cdd5c9bbc9a4a173eb5a Mon Sep 17 00:00:00 2001 From: herr kaste Date: Wed, 5 Dec 2018 22:36:17 +0100 Subject: [PATCH 8/9] Add `yield AWAIT_WORKER` to await the worker thread --- tests/test_await_worker.py | 47 ++++++++++++++++++++++++++++++++++ unittesting/__init__.py | 5 ++-- unittesting/core/__init__.py | 10 ++++++-- unittesting/core/st3/runner.py | 10 ++++++++ 4 files changed, 68 insertions(+), 4 deletions(-) create mode 100644 tests/test_await_worker.py diff --git a/tests/test_await_worker.py b/tests/test_await_worker.py new file mode 100644 index 00000000..866d34da --- /dev/null +++ b/tests/test_await_worker.py @@ -0,0 +1,47 @@ +from functools import partial +import time + +import sublime + +from unittesting import DeferrableTestCase, AWAIT_WORKER + + +def run_in_worker(fn, *args, **kwargs): + sublime.set_timeout_async(partial(fn, *args, **kwargs)) + + +class TestAwaitingWorkerInDeferredTestCase(DeferrableTestCase): + + def test_ensure_plain_yield_is_faster_than_the_worker_thread(self): + messages = [] + + def work(message, worktime=None): + # simulate that a task might take some time + # this will not yield back but block + if worktime: + time.sleep(worktime) + + messages.append(message) + + run_in_worker(work, 1, 5) + + yield + + self.assertEqual(messages, []) + + def test_await_worker(self): + messages = [] + + def work(message, worktime=None): + # simulate that a task might take some time + # this will not yield back but block + if worktime: + time.sleep(worktime) + + messages.append(message) + + run_in_worker(work, 1, 0.5) + + yield AWAIT_WORKER + + self.assertEqual(messages, [1]) diff --git a/unittesting/__init__.py b/unittesting/__init__.py index 7648f383..3c2108d6 100644 --- a/unittesting/__init__.py +++ b/unittesting/__init__.py @@ -1,4 +1,4 @@ -from .core import DeferrableTestCase +from .core import DeferrableTestCase, AWAIT_WORKER from .scheduler import UnitTestingRunSchedulerCommand from .scheduler import run_scheduler from .test_package import UnitTestingCommand @@ -22,5 +22,6 @@ "UnitTestingCurrentPackageCoverageCommand", "UnitTestingSyntaxCommand", "UnitTestingSyntaxCompatibilityCommand", - "UnitTestingColorSchemeCommand" + "UnitTestingColorSchemeCommand", + "AWAIT_WORKER" ] diff --git a/unittesting/core/__init__.py b/unittesting/core/__init__.py index 73c6b6a0..3a869e82 100644 --- a/unittesting/core/__init__.py +++ b/unittesting/core/__init__.py @@ -1,6 +1,12 @@ -from .st3.runner import DeferringTextTestRunner +from .st3.runner import DeferringTextTestRunner, AWAIT_WORKER from .st3.case import DeferrableTestCase from .st3.suite import DeferrableTestSuite from .loader import UnitTestingLoader as TestLoader -__all__ = ["TestLoader", "DeferringTextTestRunner", "DeferrableTestCase", "DeferrableTestSuite"] +__all__ = [ + "TestLoader", + "DeferringTextTestRunner", + "DeferrableTestCase", + "DeferrableTestSuite", + "AWAIT_WORKER" +] diff --git a/unittesting/core/st3/runner.py b/unittesting/core/st3/runner.py index 622073e3..09f88a80 100644 --- a/unittesting/core/st3/runner.py +++ b/unittesting/core/st3/runner.py @@ -6,9 +6,15 @@ def defer(delay, callback, *args, **kwargs): + # Rely on late binding in case a user patches it sublime.set_timeout(partial(callback, *args, **kwargs), delay) +AWAIT_WORKER = 'AWAIT_WORKER' +# Extract `set_timeout_async`, t.i. *avoid* late binding, in case a user +# patches it +run_on_worker = sublime.set_timeout_async + class DeferringTextTestRunner(TextTestRunner): """This test runner runs tests in deferred slices.""" @@ -58,6 +64,10 @@ def _continue_testing(deferred): defer(period, _wait_condition, deferred, **condition) elif isinstance(condition, int): defer(condition, _continue_testing, deferred) + elif condition == AWAIT_WORKER: + run_on_worker( + partial(defer, 0, _continue_testing, deferred) + ) else: defer(0, _continue_testing, deferred) From 8019d74bb192ba773505fbde4b63a24bd5bf0080 Mon Sep 17 00:00:00 2001 From: herr kaste Date: Wed, 5 Dec 2018 22:36:42 +0100 Subject: [PATCH 9/9] Fix and showcase single threaded testing --- tests/test_deferred_timing.py | 101 ++++++++++++++++++++-------------- 1 file changed, 61 insertions(+), 40 deletions(-) diff --git a/tests/test_deferred_timing.py b/tests/test_deferred_timing.py index 5562de48..9e802dfc 100644 --- a/tests/test_deferred_timing.py +++ b/tests/test_deferred_timing.py @@ -1,5 +1,6 @@ from functools import partial import time +from unittest.mock import patch import sublime @@ -10,51 +11,71 @@ def run_in_worker(fn, *args, **kwargs): sublime.set_timeout_async(partial(fn, *args, **kwargs)) +# When we swap `set_timeout_async` with `set_timeout` we basically run +# our program single-threaded. +# This has some benefits: +# - We avoid async/timing issues +# - We can use plain `yield` to run Sublime's task queue empty, see below +# - Every code we run will get correct coverage +# +# However note, that Sublime will just put all async events on the queue, +# avoiding the API. We cannot patch that. That means, the event handlers +# will *not* run using plain `yield` like below, you still have to await +# them using `yield AWAIT_WORKER`. +# + class TestTimingInDeferredTestCase(DeferrableTestCase): def test_a(self): - messages = [] + # `patch` doesn't work as a decorator with generator functions so we + # use `with` + with patch.object(sublime, 'set_timeout_async', sublime.set_timeout): + messages = [] + + def work(message, worktime=None): + # simulate that a task might take some time + # this will not yield back but block + if worktime: + time.sleep(worktime) - def work(message, worktime=None): - messages.append(message) - # simulate that a task might take some time - # this will not yield back but block - if worktime: - time.sleep(worktime) + messages.append(message) - def uut(): - run_in_worker(work, 1, 0.5) # add task (A) - run_in_worker(work, 2) # add task (B) + def uut(): + run_in_worker(work, 1, 0.5) # add task (A) + run_in_worker(work, 2) # add task (B) - uut() # after that task queue has: (A)..(B) - yield # add task (C) and wait for (C) - expected = [1, 2] - self.assertEqual(messages, expected) + uut() # after that task queue has: (A)..(B) + yield # add task (C) and wait for (C) + expected = [1, 2] + self.assertEqual(messages, expected) def test_b(self): - messages = [] - - def work(message, worktime=None): - messages.append(message) - if worktime: - time.sleep(worktime) - - def sub_task(): - run_in_worker(work, 2, 0.5) # add task (D) - - def uut(): - run_in_worker(work, 1, 0.5) # add task (A) - run_in_worker(sub_task) # add task (B) - - uut() - # task queue now: (A)..(B) - - yield # add task (C) and wait for (C) - # (A) runs, (B) runs and adds task (D), (C) resolves - expected = [1] - self.assertEqual(messages, expected) - # task queue now: (D) - yield # add task (E) and wait for it - # (D) runs and (E) resolves - expected = [1, 2] - self.assertEqual(messages, expected) + # `patch` doesn't work as a decorator with generator functions so we + # use `with` + with patch.object(sublime, 'set_timeout_async', sublime.set_timeout): + messages = [] + + def work(message, worktime=None): + if worktime: + time.sleep(worktime) + messages.append(message) + + def sub_task(): + run_in_worker(work, 2, 0.5) # add task (D) + + def uut(): + run_in_worker(work, 1, 0.3) # add task (A) + run_in_worker(sub_task) # add task (B) + + uut() + # task queue now: (A)..(B) + + yield # add task (C) and wait for (C) + # (A) runs, (B) runs and adds task (D), (C) resolves + expected = [1] + self.assertEqual(messages, expected) + # task queue now: (D) + yield # add task (E) and wait for it + # (D) runs and (E) resolves + expected = [1, 2] + self.assertEqual(messages, expected)