Merge pull request #114 from kormax/slow_callback_duration_logging

Add slow_callback_duration logging

Author: hosaka

qasync/__init__.py

@@ -226,6 +226,13 @@ def __exit__(self, *args):
         self.shutdown()
 
 
+def _format_handle(handle: asyncio.Handle):
+    cb = getattr(handle, "_callback", None)
+    if isinstance(getattr(cb, '__self__', None), asyncio.tasks.Task):
+        return repr(cb.__self__)
+    return str(handle)
+
+
 def _make_signaller(qtimpl_qtcore, *args):
     class Signaller(qtimpl_qtcore.QObject):
         try:
@@ -268,8 +275,22 @@ def timerEvent(self, event):  # noqa: N802
                 if handle._cancelled:
                     self.__log_debug("Handle %s cancelled", handle)
                 else:
-                    self.__log_debug("Calling handle %s", handle)
-                    handle._run()
+                    if self.__debug_enabled:
+                        # This may not be the most efficient thing to do, but it removes the need to sync
+                        # "slow_callback_duration" and "_current_handle" variables
+                        loop = asyncio.get_event_loop()
+                        try:
+                            loop._current_handle = handle
+                            self._logger.debug("Calling handle %s", handle)
+                            t0 = time.time()
+                            handle._run()
+                            dt = time.time() - t0
+                            if dt >= loop.slow_callback_duration:
+                                self._logger.warning('Executing %s took %.3f seconds', _format_handle(handle), dt)
+                        finally:
+                            loop._current_handle = None
+                    else:
+                        handle._run()
             finally:
                 del self.__callbacks[timerid]
                 handle = None

tests/test_qeventloop.py

@@ -11,6 +11,7 @@
 import socket
 import subprocess
 import sys
+import time
 from concurrent.futures import ProcessPoolExecutor, ThreadPoolExecutor
 
 import pytest
@@ -791,6 +792,22 @@ async def mycoro():
     assert not loop.is_running()
 
 
+def test_slow_callback_duration_logging(loop, caplog):
+    async def mycoro():
+        time.sleep(1)
+
+    caplog.clear()
+    loop.set_debug(True)
+    loop.slow_callback_duration = 0.1
+    with caplog.at_level(logging.WARNING):
+        loop.run_until_complete(mycoro())
+    assert len(caplog.records) == 1
+    msg = caplog.records[0].message
+    assert "Executing" in msg
+    assert "took" in msg
+    assert "seconds" in msg
+
+
 def teardown_module(module):
     """
     Remove handlers from all loggers