asyncio, Tulip issue 105: in debug mode, log callbacks taking more than 100 ms

to be executed.

1 files changed, 28 insertions, 0 deletions

diff --git a/Lib/test/test_asyncio/test_base_events.py b/Lib/test/test_asyncio/test_base_events.py
index 059b41c..352af48 100644
--- a/Lib/test/test_asyncio/test_base_events.py
+++ b/Lib/test/test_asyncio/test_base_events.py
@@ -969,6 +969,34 @@ class BaseEventLoopWithSelectorTests(test_utils.TestCase):
         with self.assertRaises(TypeError):
             self.loop.run_in_executor(None, coroutine_function)
 
+    @mock.patch('asyncio.base_events.logger')
+    def test_log_slow_callbacks(self, m_logger):
+        def stop_loop_cb(loop):
+            loop.stop()
+
+        @asyncio.coroutine
+        def stop_loop_coro(loop):
+            yield from ()
+            loop.stop()
+
+        asyncio.set_event_loop(self.loop)
+        self.loop.set_debug(True)
+        self.loop.slow_callback_duration = 0.0
+
+        # slow callback
+        self.loop.call_soon(stop_loop_cb, self.loop)
+        self.loop.run_forever()
+        fmt, *args = m_logger.warning.call_args[0]
+        self.assertRegex(fmt % tuple(args),
+                         "^Executing Handle.*stop_loop_cb.* took .* seconds$")
+
+        # slow task
+        asyncio.async(stop_loop_coro(self.loop), loop=self.loop)
+        self.loop.run_forever()
+        fmt, *args = m_logger.warning.call_args[0]
+        self.assertRegex(fmt % tuple(args),
+                         "^Executing Task.*stop_loop_coro.* took .* seconds$")
+
 
 if __name__ == '__main__':
     unittest.main()