diff --git a/qasync/__init__.py b/qasync/__init__.py index 5c51f60..732f7a2 100644 --- a/qasync/__init__.py +++ b/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 diff --git a/tests/test_qeventloop.py b/tests/test_qeventloop.py index 5c70e67..9eefc72 100644 --- a/tests/test_qeventloop.py +++ b/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