(Merge 3.4) asyncio, Tulip issue 105: in debug mode, log callbacks taking more

than 100 ms to be executed.

Lib/asyncio/base_events.py

@@ -17,6 +17,7 @@ to modify the meaning of the API call itself.
 import collections
 import concurrent.futures
 import heapq
+import inspect
 import logging
 import socket
 import subprocess
@@ -37,6 +38,15 @@ __all__ = ['BaseEventLoop', 'Server']
 _MAX_WORKERS = 5
 
 
+def _format_handle(handle):
+    cb = handle._callback
+    if inspect.ismethod(cb) and isinstance(cb.__self__, tasks.Task):
+        # format the task
+        return repr(cb.__self__)
+    else:
+        return str(handle)
+
+
 class _StopError(BaseException):
     """Raised to stop the event loop."""
 
@@ -128,6 +138,9 @@ class BaseEventLoop(events.AbstractEventLoop):
         self._clock_resolution = time.get_clock_info('monotonic').resolution
         self._exception_handler = None
         self._debug = False
+        # In debug mode, if the execution of a callback or a step of a task
+        # exceed this duration in seconds, the slow callback/task is logged.
+        self.slow_callback_duration = 0.1
 
     def __repr__(self):
         return ('<%s running=%s closed=%s debug=%s>'
@@ -823,16 +836,16 @@ class BaseEventLoop(events.AbstractEventLoop):
         if logger.isEnabledFor(logging.INFO):
             t0 = self.time()
             event_list = self._selector.select(timeout)
-            t1 = self.time()
-            if t1-t0 >= 1:
+            dt = self.time() - t0
+            if dt >= 1:
                 level = logging.INFO
             else:
                 level = logging.DEBUG
             if timeout is not None:
                 logger.log(level, 'poll %.3f took %.3f seconds',
-                           timeout, t1-t0)
+                           timeout, dt)
             else:
-                logger.log(level, 'poll took %.3f seconds', t1-t0)
+                logger.log(level, 'poll took %.3f seconds', dt)
         else:
             event_list = self._selector.select(timeout)
         self._process_events(event_list)
@@ -855,7 +868,16 @@ class BaseEventLoop(events.AbstractEventLoop):
         ntodo = len(self._ready)
         for i in range(ntodo):
             handle = self._ready.popleft()
-            if not handle._cancelled:
+            if handle._cancelled:
+                continue
+            if self._debug:
+                t0 = self.time()
+                handle._run()
+                dt = self.time() - t0
+                if dt >= self.slow_callback_duration:
+                    logger.warning('Executing %s took %.3f seconds',
+                                   _format_handle(handle), dt)
+            else:
                 handle._run()
         handle = None  # Needed to break cycles when an exception occurs.
 

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()