Repository navigation
profiling.sampling: exception mode drops samples from blocked handlers #159865
Description
Bug report
In exception mode (--mode exception), profiling.sampling writes an empty profile when the thread blocks inside an except block, for example in time.sleep(). The CLI still reports the samples as captured.
Reproduce
mock_exception.py:
import time
try:
raise ValueError("boom")
except ValueError:
time.sleep(3) # Simulate retry backoff in an exception handler.python -m profiling.sampling run --mode exception --collapsed -o output.txt mock_exception.pyCaptured 3,016 samples in 3.02 seconds
Sample rate: 999.82 samples/sec
Error rate: 0.00
Collapsed stack output written to output.txt
output.txt is empty, and the pstats (default), JSONL, flamegraph and heatmap outputs have no samples either.
Expected: the handler's stack, as --mode wall writes it. For example:
tid:24360;runpy.py:_run_module_as_main:201;runpy.py:_run_code:87;mock_exception.py:<module>:6 2999
The docs say exception mode records samples "when code is executing inside an except block where exception information is still present in the thread state", which holds while the handler sleeps.
Cause
The unwinder returns the sleeping thread correctly. The samples are dropped afterwards in Python, by a filter that exception mode does not need.
1. The CLI enables skip_idle for exception mode. _handle_run() and _handle_attach() in Lib/profiling/sampling/cli.py compute:
skip_idle = (
mode != PROFILING_MODE_WALL if mode != PROFILING_MODE_ALL else False
)Every mode except wall and all gets skip_idle=True (the live-mode handlers use mode != PROFILING_MODE_WALL). That rule is written for CPU and GIL modes, and exception mode inherits it.
2. The collector drops the thread. Collector._iter_all_frames() in Lib/profiling/sampling/collector.py:
if skip_idle:
status_flags = thread_info.status
has_gil = bool(status_flags & THREAD_STATUS_HAS_GIL)
on_cpu = bool(status_flags & THREAD_STATUS_ON_CPU)
if not (has_gil or on_cpu):
continueThe sleeping thread's status is 0x34 (MAIN_THREAD | HAS_EXCEPTION | UNKNOWN). HAS_GIL is clear because time.sleep() released the GIL, and ON_CPU is never set in exception mode because the unwinder only queries CPU state in CPU and ALL modes. The check therefore reduces to "holds the GIL", every sample of the thread is skipped, and HAS_EXCEPTION is never consulted.
3. Nothing reports an error. SampleProfiler.sample() counts an error only when reading the stack fails. The read succeeded; the drop happens afterwards inside collector.collect(). So the CLI prints Captured 3,016 samples and Error rate: 0.00 for an empty result.
Why it went unnoticed. A handler that busy-loops holds the GIL (status 0x35, HAS_GIL set) and passes the filter. The existing test_exception_mode_integration_filtering uses such a handler (x += 1 in a loop), so the bug only appears when the handler isn't holding the GIL at sampling time, e.g. while it sleeps or waits on I/O.
Checking that this filter is the only cause. --binary does not apply skip_idle, and replay builds its collector with skip_idle=False. With the same script:
python -m profiling.sampling run --mode exception --binary -o p.bin mock_exception.py
python -m profiling.sampling replay --collapsed -o replay.txt p.binreplay.txt contains the full stack (...mock_exception.py:<module>:6 2999).
Fix
Don't enable skip_idle for exception mode: the unwinder already skips threads without HAS_EXCEPTION there (unwind_stack_for_thread() in Modules/_remote_debugging/threads.c). CPU and GIL modes keep it. I have a fix ready and will open a PR.
Environment
- CPython versions tested on: CPython main branch (3.16.0a1+dev)
- Operating systems tested on: Windows 11, x86-64
- Build: Debug
Activity