Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix coroutine stack tracking #7962

Merged
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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>')
Expand All @@ -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>')
24 changes: 10 additions & 14 deletions src/tribler/core/utilities/slow_coro_detection/utils.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,3 @@
import io
from asyncio import Handle, Task
from typing import Optional

Expand All @@ -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}"
Original file line number Diff line number Diff line change
Expand Up @@ -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}")
Loading