[NO-TICKET] Profiling: Clean up logic for tracking time spent in GC by ivoanjo · Pull Request #6006 · DataDog/dd-trace-rb

ivoanjo · 2026-07-08T08:29:07Z

What does this PR do?

This PR refactors the update_time_since_previous_sample to remove the weird logic we had where cpu-time wasn't allowed to advance if we tried to sample between on_gc_start and on_gc_finish.

This logic was a leftover of past versions of the code where part of the time accounting for GC was split between on_gc_finish and sample_after_gc. Because we can't stop Ruby from GCing as many times as it wants before we're able to run sample_after_gc, this "freezing the clock" made sure we never lost GC time.

Yet, this became unneeded since #3313 as on_gc_finish immediately records all of the needed information.
Thus, we no longer need to deal with the above corner case, and we can massively simplify this logic.

Motivation:

Clean up unneeded and confusing logic.

Change log entry

None. (The whole point of this change is that this logic wasn't actually used in practice anymore)

Additional Notes:

I also took the opportunity to simplify the callers of update_time_since_previous_sample using helpers, since we were passing in a million arguments but only need to support two different cases.

How to test the change?

I've added a test that an exception gets raised if somehow a sample happens between on_gc_start and on_gc_finish.

The rest of the logic is unchanged, so existing test coverage is enough.

**What does this PR do?** This PR refactors the `update_time_since_previous_sample` to remove the weird logic we had where cpu-time wasn't allowed to advance if we tried to sample between `on_gc_start` and `on_gc_finish`. This logic was a leftover of past versions of the code where part of the time accounting for GC was split between `on_gc_finish` and `sample_after_gc`. Because we can't stop Ruby from GCing as many times as it wants before we're able to run `sample_after_gc`, this "freezing the clock" made sure we never lost GC time. Yet, this became unneeded since #3313 as `on_gc_finish` immediately records all of the needed information. Thus, we no longer need to deal with the above corner case, and we can massively simplify this logic. **Motivation:** Clean up unneeded and confusing logic. **Additional Notes:** N/A **How to test the change?** I've added a test that an exception gets raised if somehow a sample happens between `on_gc_start` and `on_gc_finish`. The rest of the logic is unchanged, so existing test coverage is enough.

We were passing ten million arguments yet only support cpu and wall-time so let's clean this up.

datadog-official · 2026-07-08T08:39:25Z

Tests

🎉 All green!

🧪 All tests passed
❄️ No new flaky tests detected

🎯 Code Coverage (details)
• Patch Coverage: 100.00%
• Overall Coverage: 90.01% (-0.03%)

_{This comment will be updated automatically if new data arrives.

🔗 Commit SHA: a062690 | Docs | Datadog PR Page | Give us feedback!}

eregon

Amazing cleanup!
Now I trust update_time_since_previous_sample does the right thing and not sometimes something fishy for the overhead :)

eregon · 2026-07-08T11:11:38Z

Maybe we can cleanup some usages & checks of INVALID_TIME after this, I'll try to take a look after this PR is merged.

…xt.c Co-authored-by: Benoit Daloze <[email protected]>

ivoanjo · 2026-07-08T13:18:32Z

Maybe we can cleanup some usages & checks of INVALID_TIME after this, I'll try to take a look after this PR is merged.

Yup... The thought crossed my mind as well. The thing that I was unsure about was how to deal with syscall failures when dealing with the clocks -- in theory they are sources of INVALID_TIME, yet I'm not sure if they actually happen in practice (what does it mean for reading the system-clock to fail? Is that even a thing?)

pr-commenter · 2026-07-08T13:42:28Z

Benchmarks

Benchmark execution time: 2026-07-08 13:42:24

Comparing candidate commit a062690 in PR branch ivoanjo/simplify-gc-tracking-logic with baseline commit 3ee518e in branch master.

Found 0 performance improvements and 0 performance regressions! Performance is the same for 48 metrics, 1 unstable metrics.

Explanation

This is an A/B test comparing a candidate commit's performance against that of a baseline commit. Performance changes are noted in the tables below as:

🟩 = significantly better candidate vs. baseline
🟥 = significantly worse candidate vs. baseline

We compute a confidence interval (CI) over the relative difference of means between metrics from the candidate and baseline commits, considering the baseline as the reference.

If the CI is entirely outside the configured SIGNIFICANT_IMPACT_THRESHOLD (or the deprecated UNCONFIDENCE_THRESHOLD), the change is considered significant.

Feel free to reach out to #apm-benchmarking-platform on Slack if you have any questions.

More details about the CI and significant changes

You can imagine this CI as a range of values that is likely to contain the true difference of means between the candidate and baseline commits.

CIs of the difference of means are often centered around 0%, because often changes are not that big:

---------------------------------(------|---^--------)-------------------------------->
                              -0.6%    0%  0.3%     +1.2%
                                 |          |        |
         lower bound of the CI --'          |        |
sample mean (center of the CI) -------------'        |
         upper bound of the CI ----------------------'

As described above, a change is considered significant if the CI is entirely outside the configured SIGNIFICANT_IMPACT_THRESHOLD (or the deprecated UNCONFIDENCE_THRESHOLD).

For instance, for an execution time metric, this confidence interval indicates a significantly worse performance:

----------------------------------------|---------|---(---------^---------)---------->
                                       0%        1%  1.3%      2.2%      3.1%
                                                  |   |         |         |
       significant impact threshold --------------'   |         |         |
                      lower bound of CI --------------'         |         |
       sample mean (center of the CI) --------------------------'         |
                      upper bound of CI ----------------------------------'

…t in GC" This reverts commit 51d0677. Aka #6006 had issues, and thus in #6012 we reverted it, and this commit restores back #6006 so we can actually fix it.

…try 2 **What does this PR do?** This PR is a second attempt at #6006 ; the first time got reverted in #6012 as we were seeing flaky failures. From DataDog/ruby-guild#314: ``` W, [2026-07-08T16:58:22.863694 #11835] WARN -- datadog: [datadog] CpuAndWallTimeWorker thread error. Operation: "rescued_sample_from_postponed_job" Cause: RuntimeError: BUG: Unexpected sample during GC (thread_id=11835 (10200), gc_tracking.cpu_time_at_start_ns=2802579244, gc_tracking.wall_time_at_start_ns=729604100602, monotonic_wall_time_now_ns=729890337067) Location: /__w/dd-trace-rb/dd-trace-rb/lib/datadog/profiling/collectors/idle_sampling_helper.rb:42:in 'Datadog::Profiling::Collectors::IdleSamplingHelper._native_idle_sampling_loop' W, [2026-07-08T16:58:22.863821 #11835] WARN -- datadog: [datadog] Failed to send telemetry before components initialization or within components lifecycle records garbage collection cycles (FAILED - 3) marks the new thread as fork-safe does not create a second thread if start is called again with allocation profiling enabled /__w/dd-trace-rb/dd-trace-rb/spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb:43: [BUG] Datadog Ruby profiler detected callback nested inside sample. Please report this at https://github.com/datadog/dd-trace-rb/blob/master/CONTRIBUTING.md#found-a-bug ruby 4.0.1 (2026-01-13 revision e04267a14b) +PRISM [x86_64-linux] ``` (The "callback nested inside sample" happens because some of our tests have strict assertions that things like object allocations can't happen, and they were failing when trying to raise that `RunntimeError: BUG: Unexpected sample during GC` as well) The problem we were seeing was due to the `#on_gc_start` specs never clearing the "thread is in GC" state and thus this state was leaking to other tests which then would trigger the assertion we added. The fix is to make sure we don't leave such leftover state; in the future #5960 is a more holistic solution to this whole "leftover state between profiler instances" problem. I recommend reviewing this PR commit-by-commit. **Motivation:** The original cleanup is useful so we definitely want to keep it! **Additional Notes:** ``` bundle exec rspec './spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb[1:2:12:1,1:2:12:2,1:2:13,1:2:15:1,1:2:16,1:2:18:1,1:2:18:2:1,1:2:20:1,1:7:1]' './spec/datadog/profiling/collectors/thread_context_spec.rb[1:3:2:1]' --seed 32922 ``` is one way of reproducing the issue. **How to test the change?** We should see a green CI and no flakiness.

ivoanjo added 2 commits July 8, 2026 08:08

Simplify callers of update_time_since_previous_sample using helpers

171f22f

We were passing ten million arguments yet only support cpu and wall-time so let's clean this up.

ivoanjo requested review from a team as code owners July 8, 2026 08:29

dd-octo-sts Bot added the profiling Involves Datadog profiling label Jul 8, 2026

eregon approved these changes Jul 8, 2026

View reviewed changes

Comment thread ext/datadog_profiling_native_extension/collectors_thread_context.c Outdated

Comment thread ext/datadog_profiling_native_extension/collectors_thread_context.c

ivoanjo and others added 2 commits July 8, 2026 14:16

Fix flaky failures from state in context leaking between tests

0d9abc7

Update ext/datadog_profiling_native_extension/collectors_thread_conte…

a062690

…xt.c Co-authored-by: Benoit Daloze <[email protected]>

ivoanjo enabled auto-merge July 8, 2026 13:20

ivoanjo merged commit 76f18e8 into master Jul 8, 2026
587 checks passed

ivoanjo deleted the ivoanjo/simplify-gc-tracking-logic branch July 8, 2026 13:44

dd-octo-sts Bot added this to the 2.38.0 milestone Jul 8, 2026

This was referenced Jul 9, 2026

Revert "[NO-TICKET] Profiling: Clean up logic for tracking time spent in GC" #6012

Merged

[PROF-6260] Enable tracking of time spent in GC #2336

Merged

[NO-TICKET] Profiling: Clean up logic for tracking time spent in GC, try 2 #6016

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

[NO-TICKET] Profiling: Clean up logic for tracking time spent in GC#6006

[NO-TICKET] Profiling: Clean up logic for tracking time spent in GC#6006
ivoanjo merged 4 commits into
masterfrom
ivoanjo/simplify-gc-tracking-logic

ivoanjo commented Jul 8, 2026

Uh oh!

datadog-official Bot commented Jul 8, 2026 •

edited by datadog-prod-us1-4 Bot

Loading

Uh oh!

eregon left a comment

Uh oh!

Uh oh!

Uh oh!

eregon commented Jul 8, 2026

Uh oh!

ivoanjo commented Jul 8, 2026

Uh oh!

pr-commenter Bot commented Jul 8, 2026

Explanation

More details about the CI and significant changes

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

ivoanjo commented Jul 8, 2026

Uh oh!

datadog-official Bot commented Jul 8, 2026 • edited by datadog-prod-us1-4 Bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

eregon left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

eregon commented Jul 8, 2026

Uh oh!

ivoanjo commented Jul 8, 2026

Uh oh!

pr-commenter Bot commented Jul 8, 2026

Benchmarks

Explanation

More details about the CI and significant changes

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

datadog-official Bot commented Jul 8, 2026 •

edited by datadog-prod-us1-4 Bot

Loading