Skip to content

Commit

Permalink
Log async stack in log_slow_async_callbacks (#280)
Browse files Browse the repository at this point in the history
  • Loading branch information
@alexmojaki
alexmojaki authored Jun 26, 2024
1 parent 80e6255 commit cedfe9b
Show file tree
Hide file tree
Showing 2 changed files with 83 additions and 14 deletions.
35 changes: 27 additions & 8 deletions logfire/_internal/async_.py
View file
Original file line number Diff line number Diff line change
@@ -1,9 +1,11 @@
from __future__ import annotations

import asyncio
import asyncio.events
import asyncio.tasks
import inspect
from contextlib import contextmanager
from pathlib import Path
from types import CoroutineType
from typing import TYPE_CHECKING, Any, ContextManager

Expand All @@ -14,6 +16,8 @@
if TYPE_CHECKING:
from .main import Logfire

ASYNCIO_PATH = str(Path(asyncio.__file__).parent.absolute())


def log_slow_callbacks(logfire: Logfire, slow_duration: float) -> ContextManager[None]:
"""Log a warning whenever a function running in the asyncio event loop blocks for too long.
Expand Down Expand Up @@ -65,6 +69,16 @@ def patch_context():

class _CallbackAttributes(StackInfo, total=False):
name: str
stack: list[StackInfo]


def stack_info_from_coroutine(coro: CoroutineType[Any, Any, Any]) -> StackInfo:
if frame := coro.cr_frame:
return get_stack_info_from_frame(frame)
else:
# This typically means that the coroutine has finished.
# We can't get an exact line number, so we'll use the line number of the code object.
return get_code_object_info(coro.cr_code)


def _callback_attributes(callback: Any) -> _CallbackAttributes:
Expand All @@ -77,15 +91,20 @@ def _callback_attributes(callback: Any) -> _CallbackAttributes:
result: _CallbackAttributes = {'name': f'task {task.get_name()}'}
if not isinstance(coro, CoroutineType): # pragma: no cover
return result
frame = coro.cr_frame
if frame:
result = {**result, **get_stack_info_from_frame(frame)}
else:
# This typically means that the coroutine has finished.
# We can't get an exact line number, so we'll use the line number of the code object.
result = {**result, **get_code_object_info(coro.cr_code)}
if function_name := result.get('code.function'): # pragma: no branch
stack_info = stack_info_from_coroutine(coro) # type: ignore
result = {**result, **stack_info}
if function_name := stack_info.get('code.function'): # pragma: no branch
result['name'] += f' ({function_name})'

# Walk through the coroutines being awaited to create an 'async stacktrace'
stack = [stack_info]
while isinstance(coro := coro.cr_await, CoroutineType):
stack_info = stack_info_from_coroutine(coro) # type: ignore
# Ignore frames from the stdlib asyncio
if not stack_info.get('code.filepath', '').startswith(ASYNCIO_PATH):
stack.append(stack_info)
result['stack'] = stack

return result

# `callback` is a callable passed to a low-level API like `call_soon`.
Expand Down
62 changes: 56 additions & 6 deletions tests/test_slow_async_callbacks.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,7 @@
from asyncio.events import Handle

import pytest
from dirty_equals import IsInt
from dirty_equals import IsInt, IsJson
from inline_snapshot import snapshot

import logfire
Expand Down Expand Up @@ -65,7 +65,16 @@ def test_slow_async_callbacks(exporter: TestExporter) -> None:
'code.lineno': 28,
'duration': 2.0,
'name': 'task foo 1 (foo)',
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{}}}',
'stack': IsJson(
[
{
'code.filepath': 'tests/import_used_for_tests/slow_async_callbacks_example.py',
'code.function': 'foo',
'code.lineno': 28,
}
]
),
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{},"stack":{"type":"array"}}}',
'logfire.tags': ('slow-async',),
},
},
Expand All @@ -85,7 +94,21 @@ def test_slow_async_callbacks(exporter: TestExporter) -> None:
'code.lineno': 15,
'duration': 2.0,
'name': 'task bar 1 (bar)',
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{}}}',
'stack': IsJson(
[
{
'code.filepath': 'tests/import_used_for_tests/slow_async_callbacks_example.py',
'code.function': 'bar',
'code.lineno': 15,
},
{
'code.filepath': 'tests/import_used_for_tests/slow_async_callbacks_example.py',
'code.function': 'foo',
'code.lineno': 28,
},
]
),
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{},"stack":{"type":"array"}}}',
'logfire.tags': ('slow-async',),
},
},
Expand All @@ -105,7 +128,16 @@ def test_slow_async_callbacks(exporter: TestExporter) -> None:
'code.lineno': 18,
'duration': 3.0,
'name': 'task bar 1 (bar)',
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{}}}',
'stack': IsJson(
[
{
'code.filepath': 'tests/import_used_for_tests/slow_async_callbacks_example.py',
'code.function': 'bar',
'code.lineno': 18,
}
]
),
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{},"stack":{"type":"array"}}}',
'logfire.tags': ('slow-async',),
},
},
Expand All @@ -125,7 +157,16 @@ def test_slow_async_callbacks(exporter: TestExporter) -> None:
'code.lineno': 28,
'duration': 2.0,
'name': 'task foo 2 (foo)',
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{}}}',
'stack': IsJson(
[
{
'code.filepath': 'tests/import_used_for_tests/slow_async_callbacks_example.py',
'code.function': 'foo',
'code.lineno': 28,
}
]
),
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{},"stack":{"type":"array"}}}',
'logfire.tags': ('slow-async',),
},
},
Expand All @@ -145,7 +186,16 @@ def test_slow_async_callbacks(exporter: TestExporter) -> None:
'code.lineno': 14,
'duration': 4.0,
'name': 'task bar 1 (bar)',
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{}}}',
'stack': IsJson(
[
{
'code.filepath': 'tests/import_used_for_tests/slow_async_callbacks_example.py',
'code.function': 'bar',
'code.lineno': 14,
}
]
),
'logfire.json_schema': '{"type":"object","properties":{"duration":{},"name":{},"stack":{"type":"array"}}}',
'logfire.tags': ('slow-async',),
},
},
Expand Down

0 comments on commit cedfe9b

Please sign in to comment.