Skip to content

fix(profiling): swap on-CPU greenlet to position 0 in unwind_greenlets - #18222

Merged
gh-worker-dd-mergequeue-cf854d[bot] merged 8 commits into
mainfrom
taegyunkim/prof-14213-fix-gevent-task-cpu-attribution
May 22, 2026
Merged

fix(profiling): swap on-CPU greenlet to position 0 in unwind_greenlets#18222
gh-worker-dd-mergequeue-cf854d[bot] merged 8 commits into
mainfrom
taegyunkim/prof-14213-fix-gevent-task-cpu-attribution

Conversation

@taegyunkim

@taegyunkim taegyunkim commented May 21, 2026

Copy link
Copy Markdown
Contributor

Description

Fixes a ~1.6× over-count of total CPU time reported by the stack v2 sampler
for gevent workloads.

ThreadInfo::sample calls render_thread_begin (creates sample S0), then
render_cpu_time (pushes the CPU delta on S0), then renders one greenlet
per current_greenlets entry via render_task_begin.

render_task_begin reuses the existing sample for the first task it sees and
starts a new sample for subsequent tasks. The new-sample path re-pushes
thread_state.cpu_time_ns whenever on_cpu=true. For asyncio this is
harmless because unwind_tasks already swaps the on-CPU task to
leaf_tasks[0], so the duplicate push never fires.

unwind_greenlets had no such swap: current_greenlets ended up in
std::unordered_map iteration order, so when the on-CPU greenlet landed at
position ≥ 1, its CPU delta was attributed twice. For M=4 workers, the
over-count converges to ~1.5-1.6× of the real CPU consumed by the process.

This change mirrors the existing unwind_tasks swap at the end of
unwind_greenlets. std::swap on std::unique_ptr<StackInfo> is a noexcept
pointer swap. on_cpu is set from snap.frame == Py_None, true only for the
currently-running greenlet, so multiple-on-CPU is impossible by construction.

Out of scope here: the deeper TODO in render_cpu_time ("thread-level CPU
time is task time") that would normalize at the task level. That's the
architectural fix the findings doc recommends; this PR is the minimal
symptom-fix.

Refs: DataDog/experimental#10595 (Phase 1 findings, Finding 3), PROF-14213.

Testing

Added tests/profiling/collector/test_stack.py::test_gevent_cpu_time_total_accuracy:

  • 4 staggered worker greenlets, each cycling ~10ms of pure-Python CPU burn
    (busy-loop on `time.process_time_ns()`) followed by `gevent.sleep(50ms)`
    for 3 seconds.
  • Ground truth: `time.process_time_ns()` delta over the timed region.
  • Profile read: sum `cpu-time` across all samples in the resulting pprof.
  • Assert: `0.85 ≤ profile_cpu / actual_cpu ≤ 1.20`.

Verified locally on Python 3.13 + gevent latest via
`scripts/run-tests --venv 177daf3`:

  • Without this fix (rebuilt main): `ratio=1.60` → test fails (upper bound
    rejects the 1.6× bug).
  • With this fix: ratio ≈ 1.0 → test passes alongside the rest of the
    profiling suite (350 tests).

A test-only companion PR demonstrates the failure on `main`: #18221.

Risks

  • C++ change is 7 lines, lives at the end of `unwind_greenlets`, and exactly
    mirrors the existing pattern in `unwind_tasks`. No header changes, no API
    changes.
  • User-visible CPU totals for gevent workloads will decrease (closer to
    actual). Release note added under `fixes:`.
  • Lower bound (0.85×) in the new test guards against a regression where the
    fix accidentally drops real CPU samples (e.g. reintroducing the
    `is_running()` gate removed in fix(profiling): always report CPU time regardless of Thread running state #16273).

Additional Notes

PLAN.md

```markdown
$(cat PLAN.md)
```

PROMPTS.md

```markdown
$(cat PROMPTS.md)
```

ThreadInfo::sample calls render_thread_begin (creates sample S0) then
render_cpu_time (pushes the CPU delta on S0), then renders one greenlet
per current_greenlets entry via render_task_begin.

render_task_begin reuses the existing sample for the first task it sees
and starts a new sample (via SampleManager::start_sample) for subsequent
tasks. The new-sample path re-pushes thread_state.cpu_time_ns whenever
on_cpu=true. For asyncio this is harmless because unwind_tasks already
swaps the on-CPU task to leaf_tasks[0], so the duplicate push never
fires. unwind_greenlets had no such swap: current_greenlets ended up in
std::unordered_map iteration order, so when the on-CPU greenlet landed
at position >= 1, its CPU delta was attributed twice and gevent CPU
totals were inflated by ~1.5-1.6x (see DataDog/experimental#10595,
Phase 1 findings, Finding 3).

This change mirrors the existing unwind_tasks swap at the end of
unwind_greenlets. std::swap on std::unique_ptr<StackInfo> is a noexcept
pointer swap. on_cpu is set from snap.frame == Py_None, true only for
the currently-running greenlet, so multiple-on-CPU is impossible by
construction.

The fix is verified by tests/profiling/collector/test_stack.py::
test_gevent_cpu_time_total_accuracy, added in this commit, which runs
M=4 staggered worker greenlets and asserts the profile cpu-time sum is
within 0.7-1.25x of time.process_time_ns() delta. Without the fix the
ratio is ~1.60; with the fix it converges to ~1.0.

Refs: DataDog/experimental#10595, PROF-14213

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
@cit-pr-commenter-54b7da

cit-pr-commenter-54b7da Bot commented May 21, 2026

Copy link
Copy Markdown

Codeowners resolved as

ddtrace/internal/datadog/profiling/stack/src/echion/threads.cc          @DataDog/profiling-python
releasenotes/notes/profiling-fix-gevent-cpu-overcount-1d2aa67778642a97.yaml  @DataDog/apm-python
tests/profiling/collector/test_stack.py                                 @DataDog/profiling-python

@datadog-prod-us1-6

datadog-prod-us1-6 Bot commented May 21, 2026

Copy link
Copy Markdown

Pipelines  Tests

Fix all issues with BitsAI

⚠️ Warnings

🚦 8 Pipeline jobs failed

DataDog/apm-reliability/dd-trace-py | build linux serverless: [arm64, cp315-cp315, v113741357-d2b8243-manylinux2014_aarch64, 1]   View in Datadog   GitLab

🔄 Retry job. This looks flaky and may succeed on retry. Failed to create pod sandbox: unable to allocate IP via local cilium agent due to no available IPs on the node.

DataDog/apm-reliability/dd-trace-py | build linux serverless: [amd64, cp315-cp315, v113741238-d2b8243-manylinux2014_x86_64, 1]   View in Datadog   GitLab

🛟 This job is unlikely to succeed on retry. Please review your pipeline configuration. NotImplementedError: This version of CPython is not supported yet during ddtrace import

DataDog/apm-reliability/dd-trace-py | build linux serverless: [arm64, cp315-cp315, v113741589-d2b8243-musllinux_1_2_aarch64, 1]   View in Datadog   GitLab

🛟 This job is unlikely to succeed on retry. Please review your pipeline configuration. Unable to access repository due to Service Unavailable error (HTTP 503) from gitretriever.

View all 8 failed jobs.

ℹ️ Info

No other issues found (see more)

🧪 All tests passed
❄️ No new flaky tests detected

Useful? React with 👍 / 👎

This comment will be updated automatically if new data arrives.
🔗 Commit SHA: 323e127 | Docs | Datadog PR Page | Give us feedback!

taegyunkim and others added 3 commits May 21, 2026 19:12
Temporary commit: changes test_gevent_cpu_time_total_accuracy to always
fail with COLLECT_RATIO=<value> in the assertion message. This makes
every CI gevent venv (across Python versions) dump the observed ratio so
we can tighten the test's bounds based on real distribution.

Will be reverted after data collection.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Replaces the temporary data-collection assert with the proper bounded
assertion. Bounds are tightened from 0.7-1.25 to 0.85-1.20 based on data
collected across local Mac (n=10) and CI Linux py3.9-3.14 (n=6).

Measured ratios with the fix applied: min=0.975, max=1.058, range
8 percentage points. Measured ratios without the fix (the bug): all
between 1.61 and 1.63 (CI, n=5). 1.20 upper rejects the bug with ~25%
margin while leaving ~13% slack above the worst observed fixed value.
0.85 lower rejects an under-count regression (e.g. reintroduction of
the is_running() gate removed in PR #16273) while leaving ~13% slack
below the worst observed fixed value.

The bounds are documented in-line as regression-detection bounds, not
a profiler accuracy claim.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
taegyunkim added a commit that referenced this pull request May 22, 2026
Match the bounds used in the companion fix PR #18222 (0.85-1.20) so this
demonstration PR exercises the same regression-detection assertion. The
bug still produces ratio ~1.6 in this branch, well above the 1.20 upper
bound, so the test fails as designed.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
taegyunkim and others added 2 commits May 21, 2026 21:30
Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
Address code review feedback:
- Split upper/lower bound explanations into two reference points each so
  the "~13% vs ~25%" framing is unambiguous.
- Rewrite stagger comment to explain the actual purpose (spreading the
  on-CPU greenlet across unordered_map iteration order) instead of
  pointing at an external measurement.
- Note in the unwind_greenlets swap comment that the greenlet "on_cpu"
  signal differs from asyncio's is_on_cpu (frame == Py_None sentinel vs
  frame matching), so a future change to that sentinel would silently
  break the swap.
- Document why no-on-CPU and empty current_greenlets cases are safe.

No behavior change.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
taegyunkim added a commit that referenced this pull request May 22, 2026
Sync the bound-comment improvements from the companion fix PR #18222.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
@taegyunkim taegyunkim added the Profiling Continous Profling label May 22, 2026
@taegyunkim
taegyunkim marked this pull request as ready for review May 22, 2026 15:15
@taegyunkim
taegyunkim requested review from a team as code owners May 22, 2026 15:15

@KowalskiThomas KowalskiThomas left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might be worth adding something or changing something in prof correctness following these changes!

Comment thread ddtrace/internal/datadog/profiling/stack/src/echion/threads.cc Outdated
@taegyunkim

Copy link
Copy Markdown
Contributor Author

Might be worth adding something or changing something in prof correctness following these changes!

@KowalskiThomas yup, that's the plan

Address review feedback on #18222: start the search at i=1, dropping
the inner i > 0 guard. If the on-CPU greenlet is already at index 0,
the loop is a no-op; otherwise the swap fires unconditionally. Safe
because:
  - Phase 1 holds greenlet_info_map_lock while reading frames, so at
    most one greenlet has frame == Py_None (on_cpu==true) per sample.
  - Empty / size-1 current_greenlets terminates the loop immediately.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
@taegyunkim

Copy link
Copy Markdown
Contributor Author

/merge

@gh-worker-devflow-routing-ef8351

gh-worker-devflow-routing-ef8351 Bot commented May 22, 2026

Copy link
Copy Markdown

View all feedbacks in Devflow UI.

2026-05-22 15:29:44 UTC ℹ️ Start processing command /merge


2026-05-22 15:29:53 UTC ℹ️ MergeQueue: waiting for PR to be ready

This pull request is not mergeable according to GitHub. Common reasons include pending required checks, missing approvals, or merge conflicts — but it could also be blocked by other repository rules or settings.
It will be added to the queue as soon as checks pass and/or get approvals. View in MergeQueue UI.
Note: if you pushed new commits since the last approval, you may need additional approval.
You can remove it from the waiting list with /remove command.


2026-05-22 19:00:15 UTC ℹ️ MergeQueue: merge request added to the queue

The expected merge time in main is approximately 54m (p90).


2026-05-22 19:35:16 UTC ℹ️ MergeQueue: This merge request was merged

@gh-worker-dd-mergequeue-cf854d
gh-worker-dd-mergequeue-cf854d Bot merged commit 0c96bea into main May 22, 2026
481 checks passed
@gh-worker-dd-mergequeue-cf854d
gh-worker-dd-mergequeue-cf854d Bot deleted the taegyunkim/prof-14213-fix-gevent-task-cpu-attribution branch May 22, 2026 19:35
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Profiling Continous Profling

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants