From b2c91556c8bc632c12fbfcec79c9d3dadb1b0dfd Mon Sep 17 00:00:00 2001
From: kormax <3392860+kormax@users.noreply.github.com>
Date: Sun, 17 Mar 2024 14:30:15 +0200
Subject: [PATCH 1/2] Add slow_callback_duration logging

---
 qasync/__init__.py | 25 +++++++++++++++++++++++--
 1 file changed, 23 insertions(+), 2 deletions(-)

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

From 4a85fb7d22665ef521e07af9549344fb939a4ca8 Mon Sep 17 00:00:00 2001
From: Alex March <alexmarch@fastmail.com>
Date: Wed, 23 Jul 2025 19:08:38 +0900
Subject: [PATCH 2/2] Add test_slow_callback_duration_logging

---
 tests/test_qeventloop.py | 17 +++++++++++++++++
 1 file changed, 17 insertions(+)

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