[NO-TICKET] Profiling: Reset per-thread state when starting profiler#5960
[NO-TICKET] Profiling: Reset per-thread state when starting profiler#5960ivoanjo wants to merge 19 commits into
Conversation
…avoid cross-profile leftover state This helper is called when the `CpuAndWallTimeWorker` is about to start, and resets all the per-thread state. This avoids any cross-state contamination, and it's also not concurrent with other things since the `CpuAndWallTimeWorker` has a built-in mechanism to make sure a given instance is the only one running at a time.
The global reset now ensures a clean slate before each test (similar to what happens in production with a new profiler run).
This ensures the need for a separate initialization step -- the global reset takes care of it all.
This reverts commit 6b56cfa. Now that `_native_global_reset_per_thread_context` runs before every test-case, the leftover state that was causing the flakiness should not happen anymore. Out of curiosity, I could manually reproduce something very close to the original flakiness with ```ruby describe "#sample_after_gvl_running" do before { skip_if_gvl_profiling_not_supported(self) } fcontext "if thread does not have per-thread context" do before { remove_per_thread_context_for(t1) } # it do # expect(sample_after_gvl_running(t1)).to be false # end it 'weird test setup' do sleep_thread = Thread.new { sleep } sample # Creates context on_gvl_released(sleep_thread) sample # Waiting starts sample # Sets skip pp per_thread_context[sleep_thread] end it "does not sample the thread" do sample_after_gvl_running(t1) expect(samples).to be_empty end end ``` And running with `--order=defined` to make sure the specs ran in this order. (There was one very subtle detail here -- the `was_skipped_at_last_sample` gets reset when the recorder is flushed so the issue in particular that made the spec flaky might not happen in practice in production since when we stop the profiler we flush the recorder)
Now that we can rely on having a `thread_context_collector_global_reset_per_thread_context` that will right-size buffers, we no longer need to keep the buffer resizing logic. I still left behind a buffer size check just in case some bug slips through.
This avoids the benchmarks needing to care about this new detail.
Typing analysisNote: Ignored files are excluded from the next sections. Untyped methodsThis PR introduces 2 partially typed methods, and clears 2 partially typed methods. It increases the percentage of typed methods from 66.05% to 66.06% (+0.01%). Partially typed methods (+2-2)❌ Introduced:If you believe a method or an attribute is rightfully untyped or partially typed, you can add |
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 5d999114af
ℹ️ About Codex in GitHub
Codex has been enabled to automatically review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
When you sign up for Codex through ChatGPT, Codex can also answer questions or update the PR, like "@codex address that feedback".
🎉 All green!🧪 All tests passed 🔗 Commit SHA: 6787b64 | Docs | Datadog PR Page | Give us feedback! |
…ing logic Codex correctly pointed out: > When `max_frames` changes during `Datadog.configure` reconfiguration, `> replace_components!` builds the new components before calling > `old.shutdown!`, and constructing the new `ThreadContext` updates the > global `latest_max_frames` while the old profiler can still be sampling. > Any thread created in that window gets a buffer sized for the new > collector, so this hard raise makes the still-running old worker report > a profiler failure instead of resizing/capping as it did before. We fix this by setting the `latest_max_frames` not at `ThreadContext` creation, but along with the global reset when the `ThreadContext` is **about to be used**. This avoids the issue above.
BenchmarksBenchmark execution time: 2026-07-03 13:32:21 Comparing candidate commit 6787b64 in PR branch Found 0 performance improvements and 0 performance regressions! Performance is the same for 48 metrics, 1 unstable metrics.
|
|
Marking as draft as my last changes were not correct + I uncovered a latent bug elsewhere |
I saw this blowing up in CI due to some other errors on the branch, and in practice raising exceptions here is never correct and it was good that Ruby complained.
|
Ok, I believe this is finally in good shape for review! |
|
|
||
| // Reset per-thread state, if any. This ensures there's no leftover state from a previous profiler run that would | ||
| // affect or be included in samples taken by this profiler about to run. | ||
| thread_context_collector_global_reset_per_thread_context(state->thread_context_collector_instance); |
There was a problem hiding this comment.
| thread_context_collector_global_reset_per_thread_context(state->thread_context_collector_instance); | |
| thread_context_collector_global_reset_all_per_thread_contexts(state->thread_context_collector_instance); |
Seems clearer, otherwise it sounds like it resets only one
There was a problem hiding this comment.
_global might be redundant then and could be dropped
There was a problem hiding this comment.
Renamed to thread_context_collector_reset_all_per_thread_contexts in 1213b3c
eregon
left a comment
There was a problem hiding this comment.
We should check that there is only 1 active TheadContext at a time, since we rely on that for this global reset and notably for latest_max_frames, could you add such a check?
| // | ||
| // Note that tests call this method directly in the same process without forking, | ||
| // and in such a case non-current Threads keep running. |
There was a problem hiding this comment.
Could you keep this note? It's still very surprising that this method gets called by tests while the first line claims it's only called in the child process.
There was a problem hiding this comment.
The "non-concurrent threads" note is a bit confusing so I've rephrased this in 79370c6, let me know what you think.
eregon
left a comment
There was a problem hiding this comment.
Great stuff, this feels much cleaner and less brittle than explicitly clearing contexts, because we global reset only at known "safe points" i.e. when the profiler is stopped and all hooks are reliably disabled
| // This buffer was not initialized. This can happen if `sampling_buffer_check_max_frames` fails during initialize, | ||
| // although in practice that shouldn't happen either. @ivoanjo: We can't raise an exception here, this gets called | ||
| // by the Ruby GC, but I hesitated on dropping an `rb_bug` since it is possible to trigger this if we pass a wrong | ||
| // `max_frames`. |
There was a problem hiding this comment.
This sounds very defensive programming, also in the wording.
although in practice that shouldn't happen either
I'd say let's rb_bug() then. Or if that's not true and it can be easily repro'd then not claim that in the comment
since it is possible to trigger this if we pass a wrong
max_frames.
That's basically contradicting the above
There was a problem hiding this comment.
Idk... I feel like rb_bug should be for "THIS SHOULD NEVER EVER HAPPEN", and for this one we could have some weird bug that triggers this (e.g. in our tests).
E.g. we should be careful with rb_bug since it will blow up in production, and I'm pretty sure nobody will be very happy if their app blows up because of a Datadog bug.
| return instance; | ||
| } | ||
|
|
||
| static VALUE _native_initialize(int argc, VALUE *argv, DDTRACE_UNUSED VALUE _self) { |
There was a problem hiding this comment.
Should we have a check here that thread_context_collector_global_reset_per_thread_context() has been called, e.g. checking current thread has a per_thread_context? The failure might be quite obscure otherwise.
| // | ||
| // Assumption: Can only be called when the CpuAndWallTimeWorker is stopped (e.g. no tracepoints active, no signals | ||
| // triggering samples, no gvl hooks, etc). | ||
| void thread_context_collector_global_reset_per_thread_context(VALUE self_instance) { |
There was a problem hiding this comment.
One more reason to check single active ThreadContext, getting the max_frames wouldn't be well-defined otherwise with e.g. 2 ThreadContext's with different max_frames.
| // | ||
| // Note that tests call this method directly in the same process without forking, | ||
| // and in such a case non-current Threads keep running. |
There was a problem hiding this comment.
I'd like to keep this note, it confused the hell out of me & Claude too
There was a problem hiding this comment.
Hmmm I kinda disagree on keeping it in ThreadContext.
I think it still makes sense to have some reference in the CpuAndWallTimeWorker (which I've added in 79370c6 ).
Yet... in ThreadContext this function is only clearing the stats so... I'm not sure it warrants this note?
| # Seed state from sampling | ||
| start | ||
| try_wait_until do | ||
| samples_for_thread(samples_from_pprof_without_gc_and_overhead(recorder.serialize!), Thread.current).any? |
There was a problem hiding this comment.
Maybe not for this PR but samples_from_pprof_without_gc_and_overhead feels brittle (I'd remove it if we can), typically we had to change to CPU/wall > 0 instead for several tests
| elapsed_ns = Datadog::Core::Utils::Time.get_time(:nanosecond) - before_restart_ns | ||
|
|
||
| cpu_time_ns = new_samples.sum { |it| it.values.fetch(:"cpu-time") } | ||
| expect(cpu_time_ns).to be <= elapsed_ns |
There was a problem hiding this comment.
I find it dangerous to compare CPU and wall time, can we just use CPU time for elapsed_ns?
Or wall time for both?
| before do | ||
| thread_context_collector | ||
| remove_per_thread_context_for(Thread.current) | ||
| end |
There was a problem hiding this comment.
This is very brittle because N tests need this.
I think either:
- global reset in before(:all)
- call
thread_context_collectorfromremove_per_thread_context_for(seems nicer and expresses the dependency cleanly)
| second_samples = samples_from_pprof(second_recorder.serialize!) | ||
| current_thread_samples = samples_for_thread(second_samples, Thread.current) | ||
| main_sample = current_thread_samples.find { |s| !s.labels.key?(:"profiler overhead") } | ||
| main_sample = samples_for_thread(samples, Thread.current).find { |it| !it.labels.key?(:"profiler overhead") } |
There was a problem hiding this comment.
Can current Thread have a profiler overhead sample? I'd think not
| cpu_time_at_previous_sample_ns: invalid_time, | ||
| wall_time_at_previous_sample_ns: invalid_time, |
There was a problem hiding this comment.
This will fail with my eager init times PR #5988.
Can we check something else to be reset to avoid a semantic conflict between both PRs?
| // This MUST be called before profiling starts, so that a new profiler session starts from a fresh state and never | ||
| // observes or includes any leftover stale state from a previous session. | ||
| // | ||
| // It updates the global `latest_max_frames` from the given (latest) ThreadContext and (re)creates every per-thread | ||
| // context's sampling buffer sized accordingly, so the buffers always match the collector that's about to start | ||
| // sampling -- even if a previous session used a different max_frames. | ||
| // | ||
| // Assumption: Can only be called when the CpuAndWallTimeWorker is stopped (e.g. no tracepoints active, no signals | ||
| // triggering samples, no gvl hooks, etc). |
There was a problem hiding this comment.
Minor: the comments order here seems suboptimal.
For me the Assumption is the main thing, maybe we should have that first.
And then the rest is really about other components must call this at well-defined places, so maybe that part should be there and not here?
…, got `nil` **What does this PR do?** This PR fixes the flaky profiling spec we saw in https://github.com/DataDog/dd-trace-rb/actions/runs/28523919081/job/84555219767 : ``` Failures: 1) Datadog::Profiling::Collectors::CpuAndWallTimeWorker#start when using the no signals workaround always simulates signal delivery Failure/Error: expect(sample_count).to be > 0 expected: > 0 got: nil # ./spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb:699:in `block (4 levels) in <top (required)>' # ./spec/spec_helper.rb:313:in `block (2 levels) in <top (required)>' # ./spec/spec_helper.rb:207:in `block (2 levels) in <top (required)>' # /usr/local/bundle/gems/webmock-3.26.2/lib/webmock/rspec.rb:39:in `block (2 levels) in <top (required)>' # /usr/local/bundle/gems/rspec-wait-0.0.10/lib/rspec/wait.rb:47:in `block (2 levels) in <top (required)>' # ./spec/support/execute_in_fork.rb:32:in `run' Finished in 17.45 seconds (files took 0.96839 seconds to load) 812 examples, 1 failure, 113 pending Failed examples: rspec ./spec/datadog/profiling/collectors/cpu_and_wall_time_worker_spec.rb:678 # Datadog::Profiling::Collectors::CpuAndWallTimeWorker#start when using the no signals workaround always simulates signal delivery ``` TL;DR the problem here is that when this spec was written, ``` all_samples = try_wait_until do samples = samples_from_pprof_without_gc_and_overhead(recorder.serialize!) samples if samples.any? end ``` If you saw any samples that were NOT GC and NOT overhead, then for sure you were seeing a regular "sampled all the threads" event, and thus the current thread was for sure going to be in there. This is no longer the case now that we have a mechanism for special-casing internal profiler threads and threads without the GVL (as well as sometimes leftover state -- that's being addressed in DataDog#5960 ). Thus the TL;DR as far as this test cares, it can't just assume that if there's any samples in there, those would be the samples it's expecting to get. To fix this, we check that we have samples for the current thread, which was the underlying assumption/expectation that wasn't being stated. **Motivation:** Zero flakiness in profiling! **Additional Notes:** There were a few other specs that we changed recently for similar reasons -- they were written in simpler times ;) Also, I gave a pass overall on this file to make sure there weren't other specs encoding the same wrong assumption that would flake in the future but as far as I saw, this is the last one. **How to test the change?** Green CI
… `thread_context_collector_reset_all_per_thread_contexts`
Co-authored-by: Benoit Daloze <eregontp@gmail.com>
What does this PR do?
This PR introduces a new
thread_context_collector_global_reset_per_thread_contextfunction in theThreadContextcollector.This function, as the name indicates, resets all of the per-thread context we keep, and is called by the
CpuAndWallTimeWorkerright before profiling starts so that we always start with a known-good blank slate, which fixes a few issues (discussed below) of stale state resulting in surprising behaviors.This also allows us to simplify a few things in the code, as we get all of the below "naturally" from this reset:
sampling_bufferresizes (it comes naturally from reallocating a new buffer at the start of profiling)thread_begin_tracepointMotivation:
Since #5816, we've been keeping the profiler's per-thread context directly attached to each Ruby thread.
This has a number of advantages:
Yet, because the per-thread context was being retained from profiler run to profiler run, we ran into a few rare corner cases:
In #5926 (comment) you can see a screenshot of a 1 second profile with 6 seconds of cpu/wall-time blamed on a single sample, representing that gap when the profiler was stopped.
Some of our tests had very strict assertions so we were playing whack-a-mole with "oh what if this one piece of leftover state was there between tests".
Change log entry
Yes. Profiling: Fix left-over state impacting samples when profiler gets stopped and started again
Additional Notes:
This is my third attempt at addressing this issue, and in particular it replaces the earlier #5926 .
How to test the change?
I've added code coverage for the new behavior, including a spec that asserts there's no carry-over state between executions of the profiler/
CpuAndWallTimeWorker.