Issue #33: Add slow_callback_duration property to loop

Author: 1st1

tests/test_base.py

@@ -288,6 +288,38 @@ async def foo():
         with self.assertRaisesRegex(ValueError, 'aaa'):
             self.loop.run_until_complete(foo())
 
+    def test_debug_slow_callbacks(self):
+        logger = logging.getLogger('asyncio')
+        self.loop.set_debug(True)
+        self.loop.slow_callback_duration = 0.2
+        self.loop.call_soon(lambda: time.sleep(0.3))
+
+        with mock.patch.object(logger, 'warning') as log:
+            self.loop.run_until_complete(asyncio.sleep(0, loop=self.loop))
+
+        self.assertEqual(log.call_count, 1)
+        # format message
+        msg = log.call_args[0][0] % log.call_args[0][1:]
+
+        self.assertIn('Executing <Handle', msg)
+        self.assertIn('test_debug_slow_callbacks', msg)
+
+    def test_debug_slow_timer_callbacks(self):
+        logger = logging.getLogger('asyncio')
+        self.loop.set_debug(True)
+        self.loop.slow_callback_duration = 0.2
+        self.loop.call_later(0.01, lambda: time.sleep(0.3))
+
+        with mock.patch.object(logger, 'warning') as log:
+            self.loop.run_until_complete(asyncio.sleep(0.02, loop=self.loop))
+
+        self.assertEqual(log.call_count, 1)
+        # format message
+        msg = log.call_args[0][0] % log.call_args[0][1:]
+
+        # self.assertIn('Executing <Handle', msg)
+        # self.assertIn('test_debug_slow_callbacks', msg)
+
     def test_default_exc_handler_callback(self):
         self.loop._process_events = mock.Mock()
 

uvloop/cbhandles.pyx

@@ -97,17 +97,34 @@ cdef class Handle:
     cdef _cancel(self):
         self.cancelled = 1
         self.callback = NULL
-        self.arg1 = self.arg2 = self.arg3 = self.arg4 = None
+        self.arg2 = self.arg3 = self.arg4 = None
 
     # Public API
 
     def __repr__(self):
+        info = [self.__class__.__name__]
+
         if self.cancelled:
-            return '<Handle cancelled {:#x}>'.format(id(self))
+            info.append('cancelled')
+
+        if self.cb_type == 1:
+            func = self.arg1
+            if hasattr(func, '__qualname__'):
+                cb_name = getattr(func, '__qualname__')
+            elif hasattr(func, '__name__'):
+                cb_name = getattr(func, '__name__')
+            else:
+                cb_name = repr(func)
+
+            info.append(cb_name)
         else:
-            return '<Handle {!r} {:#x}>'.format(
-                self.arg1 if self.cb_type == 1 else self.meth_name,
-                id(self))
+            info.append(self.meth_name)
+
+        if self._source_traceback is not None:
+            frame = self._source_traceback[-1]
+            info.append('created at {}:{}'.format(frame[0], frame[1]))
+
+        return '<' + ' '.join(info) + '>'
 
     def cancel(self):
         self._cancel()
@@ -177,6 +194,8 @@ cdef class TimerHandle:
             if old_exec_py_code == 1:
                 raise RuntimeError('Python exec-mode before TimerHandle._run')
         self.loop._executing_py_code = 1
+        if self.loop._debug:
+            started = time_monotonic()
         try:
             if args is not None:
                 callback(*args)
@@ -193,17 +212,40 @@ cdef class TimerHandle:
                 context['source_traceback'] = self._source_traceback
 
             self.loop.call_exception_handler(context)
+        else:
+            if self.loop._debug:
+                delta = time_monotonic() - started
+                if delta > self.loop.slow_callback_duration:
+                    aio_logger.warning(
+                        'Executing %r took %.3f seconds',
+                        self, delta)
         finally:
             self.loop._executing_py_code = old_exec_py_code
             Py_DECREF(self)
 
     # Public API
 
     def __repr__(self):
+        info = [self.__class__.__name__]
+
         if self.closed:
-            return '<TimerHandle cancelled {:#x}>'.format(id(self))
+            info.append('cancelled')
+
+        func = self.callback
+        if hasattr(func, '__qualname__'):
+            cb_name = getattr(func, '__qualname__')
+        elif hasattr(func, '__name__'):
+            cb_name = getattr(func, '__name__')
         else:
-            return '<TimerHandle {!r} {:#x}>'.format(self.callback, id(self))
+            cb_name = repr(func)
+
+        info.append(cb_name)
+
+        if self._source_traceback is not None:
+            frame = self._source_traceback[-1]
+            info.append('created at {}:{}'.format(frame[0], frame[1]))
+
+        return '<' + ' '.join(info) + '>'
 
     def cancel(self):
         self._cancel()

uvloop/includes/stdlib.pxi

@@ -112,6 +112,7 @@ cdef subprocess_SubprocessError = subprocess.SubprocessError
 cdef int signal_NSIG = std_signal.NSIG
 
 cdef time_sleep = time.sleep
+cdef time_monotonic = time.monotonic
 
 cdef tb_extract_stack = traceback.extract_stack
 cdef tb_format_list = traceback.format_list

uvloop/loop.pxd

@@ -36,6 +36,8 @@ cdef class Loop:
 
         bint _coroutine_wrapper_set
 
+        public slow_callback_duration
+
         readonly bint _closed
         bint _debug
         bint _running

uvloop/loop.pyx

@@ -57,6 +57,8 @@ cdef class Loop:
         if self.uvloop is NULL:
             raise MemoryError()
 
+        self.slow_callback_duration = 0.1
+
         self._closed = 0
         self._debug = 0
         self._thread_is_main = 0
@@ -230,14 +232,32 @@ cdef class Loop:
             self._check_sigint()
 
         ntodo = len(self._ready)
-        for i from 0 <= i < ntodo:
-            handler = <Handle> popleft()
-            if handler.cancelled == 0:
-                try:
-                    handler._run()
-                except BaseException as ex:
-                    self._stop(ex)
-                    return
+        if self._debug:
+            for i from 0 <= i < ntodo:
+                handler = <Handle> popleft()
+                if handler.cancelled == 0:
+                    try:
+                        started = time_monotonic()
+                        handler._run()
+                    except BaseException as ex:
+                        self._stop(ex)
+                        return
+                    else:
+                        delta = time_monotonic() - started
+                        if delta > self.slow_callback_duration:
+                            aio_logger.warning(
+                                'Executing %r took %.3f seconds',
+                                handler, delta)
+
+        else:
+            for i from 0 <= i < ntodo:
+                handler = <Handle> popleft()
+                if handler.cancelled == 0:
+                    try:
+                        handler._run()
+                    except BaseException as ex:
+                        self._stop(ex)
+                        return
 
         if len(self._queued_streams):
             self._exec_queued_writes()