Merge pull request #7962 from kozlovsky/fix/coroutine_stack_tracking

Fix coroutine stack tracking

src/tribler/core/utilities/slow_coro_detection/tests/test_slow_coro_detection.py

@@ -86,7 +86,7 @@ def test__report_freeze_first_report(logger, format_info):
     _report_freeze(handle, duration, first_report=True)
     format_info.assert_called_with(handle, include_stack=True, stack_cut_duration=pytest.approx(8.0))
     logger.error.assert_called_with(
-        'Slow coroutine is occupying the loop for 10.000 seconds already: <formatted handle>')
+        'A slow coroutine step is occupying the loop for 10.000 seconds already: <formatted handle>')
 
 
 @patch('tribler.core.utilities.slow_coro_detection.watching_thread.format_info', return_value='<formatted handle>')
@@ -98,4 +98,5 @@ def test__report_freeze_not_first_report(logger, format_info):
     _report_freeze(handle, duration, first_report=False)
     format_info.assert_called_with(handle, include_stack=True, stack_cut_duration=pytest.approx(8.0),
                                    limit=2, enable_profiling_tip=False)
-    logger.error.assert_called_with('Still executing <formatted handle>')
+    logger.error.assert_called_with(
+        'Still executing the slow coroutine step for 10.000 seconds already: <formatted handle>')

src/tribler/core/utilities/slow_coro_detection/utils.py

@@ -1,4 +1,3 @@
-import io
 from asyncio import Handle, Task
 from typing import Optional
 
@@ -16,20 +15,17 @@ def format_info(handle: Handle, include_stack: bool = False, stack_cut_duration:
     """
     func = handle._callback
     task: Task = getattr(func, '__self__', None)
-    if not isinstance(task, Task):
+    if not isinstance(task, Task) and func.__class__.__name__ not in {"TaskWakeupMethWrapper", "task_wakeup"}:
         return repr(func)
 
+    task_repr = repr(task) if task is not None else repr(func)
+
     if not include_stack:
-        return repr(task)
-
-    if not main_stack_tracking_is_enabled():
-        stream = io.StringIO()
-        try:
-            task.print_stack(limit=limit, file=stream)
-        except Exception as e:  # pylint: disable=broad-except
-            stack = f'Stack is unavailable: {e.__class__.__name__}: {e}'
-        else:
-            stack = stream.getvalue()
-    else:
+        return task_repr
+
+    if main_stack_tracking_is_enabled():
         stack = get_main_thread_stack(stack_cut_duration, limit, enable_profiling_tip)
-    return f"{task}\n{stack}"
+    else:
+        stack = 'Set SLOW_CORO_STACK_TRACING=1 to see the coroutine stack'
+
+    return f"{task_repr}\n{stack}"

src/tribler/core/utilities/slow_coro_detection/watching_thread.py

@@ -88,9 +88,9 @@ def _report_freeze(handle: Handle, duration: float, first_report: bool):
 
     if first_report:
         info_str = format_info(handle, include_stack=True, stack_cut_duration=stack_cut_duration)
-        logger.error(f'Slow coroutine is occupying the loop for {duration:.3f} seconds already: {info_str}')
+        logger.error(f'A slow coroutine step is occupying the loop for {duration:.3f} seconds already: {info_str}')
         return
 
     info_str = format_info(handle, include_stack=True, stack_cut_duration=stack_cut_duration, limit=2,
                            enable_profiling_tip=False)
-    logger.error(f"Still executing {info_str}")
+    logger.error(f"Still executing the slow coroutine step for {duration:.3f} seconds already: {info_str}")