Attempt to fix bug where speech could not be interrupted during some race conditions.

tests/test_debug_startup_timing.py

@@ -0,0 +1,79 @@
+import sys
+import unittest
+from pathlib import Path
+from unittest import mock
+
+sys.path.insert(0, str(Path(__file__).resolve().parents[1] / "src"))
+
+from cthulhu import debug
+
+
+class DebugStartupTimingTests(unittest.TestCase):
+    def setUp(self) -> None:
+        self._debugLevel = debug.debugLevel
+        self._startupTimingEnabled = debug.startupTimingEnabled
+        self._startupTimingStartTime = debug._startupTimingStartTime
+        self._startupTimingLastTime = debug._startupTimingLastTime
+        debug.debugLevel = debug.LEVEL_SEVERE
+        debug.startupTimingEnabled = False
+        debug._startupTimingStartTime = None
+        debug._startupTimingLastTime = None
+
+    def tearDown(self) -> None:
+        debug.debugLevel = self._debugLevel
+        debug.startupTimingEnabled = self._startupTimingEnabled
+        debug._startupTimingStartTime = self._startupTimingStartTime
+        debug._startupTimingLastTime = self._startupTimingLastTime
+
+    def test_startup_timing_is_silent_when_disabled_and_debug_is_not_enabled(self) -> None:
+        with mock.patch.object(debug, "println") as println:
+            debug.print_startup_timing("hidden phase")
+
+        println.assert_not_called()
+
+    def test_startup_timing_logs_when_explicitly_enabled(self) -> None:
+        with mock.patch.object(debug.time, "monotonic", side_effect=[10.0, 10.25]):
+            debug.set_startup_timing_enabled(True)
+            with mock.patch.object(debug, "println") as println:
+                debug.print_startup_timing("explicit phase")
+
+        println.assert_called_once_with(
+            debug.LEVEL_SEVERE,
+            "STARTUP TIMING: explicit phase: +0.250s, total 0.250s",
+            True,
+            False,
+        )
+
+    def test_startup_timing_logs_when_debug_output_is_enabled(self) -> None:
+        debug.debugLevel = debug.LEVEL_INFO
+        with mock.patch.object(debug.time, "monotonic", return_value=20.0):
+            with mock.patch.object(debug, "println") as println:
+                debug.print_startup_timing("debug phase")
+
+        println.assert_called_once_with(
+            debug.LEVEL_INFO,
+            "STARTUP TIMING: debug phase: +0.000s, total 0.000s",
+            True,
+            False,
+        )
+
+    def test_startup_timing_context_logs_start_and_end(self) -> None:
+        with mock.patch.object(debug.time, "monotonic", side_effect=[30.0, 30.1, 30.4]):
+            debug.set_startup_timing_enabled(True)
+            with mock.patch.object(debug, "println") as println:
+                with debug.startup_timing("wrapped phase"):
+                    pass
+
+        self.assertEqual(2, println.call_count)
+        self.assertEqual(
+            "STARTUP TIMING: wrapped phase start: +0.100s, total 0.100s",
+            println.call_args_list[0].args[1],
+        )
+        self.assertEqual(
+            "STARTUP TIMING: wrapped phase end: +0.300s, total 0.400s",
+            println.call_args_list[1].args[1],
+        )
+
+
+if __name__ == "__main__":
+    unittest.main()