using pyinstrument to log traceback of slow callbacks (#2341)

* using pyinstrument to keep track of slow callbacks

* using similar logging message a sbefore

* no more errors in development mode

* fixes issues with testing and development mode on reboots

* /slow callback was being resolved in 1.1 seconds
causing test_unhealthy_app_with_slow_callbacks
to fail

* changed assert from 2.0 to 1.0 second

* reverting back to 2.0 seconds
raising /slow to 2.0 seocnds

* fixed indentation

* added comment about the indentation

* trying to improve performance

Co-authored-by: Andrei Neagu <[email protected]>

Author: GitHK

packages/service-library/requirements/_base.in

@@ -22,6 +22,8 @@ sqlalchemy
 psycopg2-binary
 pyyaml
 
+# used for monitoring of slow callbacks
+pyinstrument
 
 # These are limitations introduced by testing libraries
 

packages/service-library/requirements/_base.txt

@@ -73,6 +73,10 @@ psycopg2-binary==2.8.6
     #   sqlalchemy
 pydantic==1.8.2
     # via -r requirements/_base.in
+pyinstrument-cext==0.2.4
+    # via pyinstrument
+pyinstrument==3.4.2
+    # via -r requirements/_base.in
 pyrsistent==0.17.3
     # via jsonschema
 pyyaml==5.4.1

packages/service-library/src/servicelib/monitor_slow_callbacks.py

@@ -1,13 +1,15 @@
 import asyncio.events
 import time
-from asyncio.base_events import _format_handle
+import sys
 from typing import List
 
+from pyinstrument import Profiler
+
 from .incidents import SlowCallback
 
 
 def enable(slow_duration_secs: float, incidents: List[SlowCallback]) -> None:
-    """ Based in from aiodebug
+    """Based in from aiodebug
 
     Patches ``asyncio.events.Handle`` to report an incident every time a callback
     takes ``slow_duration_secs`` seconds or more to run.
@@ -19,13 +21,26 @@ def enable(slow_duration_secs: float, incidents: List[SlowCallback]) -> None:
     _run = asyncio.events.Handle._run
 
     def instrumented(self):
-        t0 = time.monotonic()
-        retval = _run(self)
-        dt = time.monotonic() - t0
+        # unsetting profiler, helps with development mode and tests
+        sys.setprofile(None)
+
+        with Profiler(interval=slow_duration_secs) as profiler:
+            t0 = time.monotonic()
+
+            retval = _run(self)
+
+            dt = time.monotonic() - t0
+
         if dt >= slow_duration_secs:
-            task_info = _format_handle(self)
-            incidents.append(SlowCallback(msg=task_info, delay_secs=dt))
-            logger.warning("Executing %s took %.3f seconds", task_info, dt)
+            # the indentation is correct, the profiler needs to be stopped when
+            # printing the output, the profiler is started and stopped by the
+            # contextmanger
+            profiler_result = profiler.output_text(
+                unicode=True, color=False, show_all=True
+            )
+            incidents.append(SlowCallback(msg=profiler_result, delay_secs=dt))
+            logger.warning("Executing took %.3f seconds\n%s", dt, profiler_result)
+
         return retval
 
     asyncio.events.Handle._run = instrumented

services/web/server/tests/unit/isolated/test_healthcheck.py

@@ -70,7 +70,7 @@ async def _check_entrypoint():
 
 @pytest.fixture
 def client(loop, aiohttp_unused_port, aiohttp_client, api_version_prefix):
-    SLOW_HANDLER_DELAY_SECS = 1.0  # secs
+    SLOW_HANDLER_DELAY_SECS = 2.0  # secs
 
     # pylint:disable=unused-variable
     routes = web.RouteTableDef()