Repository navigation
--async-aware profiles show event loop internals under tasks #159645
Description
Bug report
--async-aware profiles show event loop frames under tasks instead of their await chain
Repro:
import asyncio
async def spin():
while True:
await asyncio.sleep(0)
asyncio.run(spin())Run:
sudo ./python.exe -m profiling.sampling run -d 2 --async-aware repro.py
Actual:
Captured 2,000 samples in 2.00 seconds
Sample rate: 999.94 samples/sec
Error rate: 0.65
Profile Stats:
nsamples sample% tottime (ms) cumul% cumtime (ms) filename:lineno(function)
9/9 47.4 9.000 47.4 9.000 selectors.py:548(KqueueSelector.select)
7/7 36.8 7.000 36.8 7.000 repro.py:5(spin)
2/3 10.5 2.000 15.8 3.000 tasks.py:711(sleep)
1/1 5.3 1.000 5.3 1.000 tasks.py:696(__sleep0)
0/1 0.0 0.000 5.3 1.000 base_events.py:2090(BaseEventLoop._run_once)
0/9 0.0 0.000 47.4 9.000 base_events.py:683(BaseEventLoop.run_forever)
0/9 0.0 0.000 47.4 9.000 base_events.py:712(BaseEventLoop.run_until_complete)
0/9 0.0 0.000 47.4 9.000 runners.py:128(Runner.run)
0/9 0.0 0.000 47.4 9.000 runners.py:205(run)
0/9 0.0 0.000 47.4 9.000 repro.py:7(<module>)
0/9 0.0 0.000 47.4 9.000 _sync_coordinator.py:201(_execute_script)
0/9 0.0 0.000 47.4 9.000 _sync_coordinator.py:254(main)
0/9 0.0 0.000 47.4 9.000 _sync_coordinator.py:261(<module>)
0/9 0.0 0.000 47.4 9.000 <frozen runpy>:87(_run_code)
0/9 0.0 0.000 47.4 9.000 <frozen runpy>:201(_run_module_as_main)
Legend:
nsamples: Direct/Cumulative samples (direct executing / on call stack)
sample%: Percentage of total samples this function was directly executing
tottime: Estimated total time spent directly in this function
cumul%: Percentage of total samples when this function was on the call stack
cumtime: Estimated cumulative time (including time in called functions)
filename:lineno(function): Function location and name
Summary of Interesting Functions:
Functions with Highest Direct/Cumulative Ratio (Hot Spots):
1.000 direct/cumulative ratio, 47.4% direct samples: selectors.py:(KqueueSelector.select)
1.000 direct/cumulative ratio, 36.8% direct samples: repro.py:(spin)
1.000 direct/cumulative ratio, 5.3% direct samples: tasks.py:(__sleep0)
Functions with Highest Call Frequency (Indirect Calls):
9 indirect calls, 47.4% total stack presence: base_events.py:(BaseEventLoop.run_forever)
9 indirect calls, 47.4% total stack presence: base_events.py:(BaseEventLoop.run_until_complete)
9 indirect calls, 47.4% total stack presence: runners.py:(Runner.run)
Functions with Highest Call Magnification (Cumulative/Direct):
1.5x call magnification, 1 indirect calls from 2 direct: tasks.py:(sleep)
Expected:
Captured 2,000 samples in 2.00 seconds
Sample rate: 999.94 samples/sec
Error rate: 0.00
Profile Stats:
nsamples sample% tottime (ms) cumul% cumtime (ms) filename:lineno(function)
52/52 100.0 52.000 100.0 52.000 tasks.py:711(sleep)
0/52 0.0 0.000 100.0 52.000 repro.py:5(spin)
0/52 0.0 0.000 100.0 52.000 <task>:0(Task-1)
Legend:
nsamples: Direct/Cumulative samples (direct executing / on call stack)
sample%: Percentage of total samples this function was directly executing
tottime: Estimated total time spent directly in this function
cumul%: Percentage of total samples when this function was on the call stack
cumtime: Estimated cumulative time (including time in called functions)
filename:lineno(function): Function location and name
Summary of Interesting Functions:
Functions with Highest Direct/Cumulative Ratio (Hot Spots):
1.000 direct/cumulative ratio, 100.0% direct samples: tasks.py:(sleep)
Functions with Highest Call Frequency (Indirect Calls):
52 indirect calls, 100.0% total stack presence: repro.py:(spin)
52 indirect calls, 100.0% total stack presence: <task>:(Task-1)
Functions with Highest Call Magnification (Cumulative/Direct):
➜ cpython git:(main) ✗
async profiler should not capture the event loop internals
and the docs say so on profiling.sampling.rst:1425–1428:
Standard profiling of async code can be confusing because the physical call
stack often shows event loop internals rather than the logical flow of your
coroutines. Async-aware mode addresses this by tracking which task is running
and presenting stacks that reflect the ``await`` chain.
Proposed fix: use the live call stack only while the task's coroutine is executing.
I have a fix ready
CPython versions tested on:
CPython main branch
Operating systems tested on:
macOS
Activity