[Tracer] Tolerate clock skew when reparenting Activities to active Span#8674
Merged
Conversation
github-actions
Bot
added
the
area:tracer
NachoEchevarria
changed the title
BenchmarksBenchmark execution time: 2026-05-22 09:57:44 Comparing candidate commit 089b98f in PR branch Found 0 performance improvements and 1 performance regressions! Performance is the same for 71 metrics, 0 unstable metrics, 62 known flaky benchmarks, 64 flaky benchmarks without significant changes.
|
Execution-Time Benchmarks Report ⏱️Execution-time results for samples comparing This PR (8674) and master. ✅ No regressions detected - check the details below Full Metrics ComparisonFakeDbCommand
HttpMessageHandler
Comparison explanationExecution-time benchmarks measure the whole time it takes to execute a program, and are intended to measure the one-off costs. Cases where the execution time results for the PR are worse than latest master results are highlighted in **red**. The following thresholds were used for comparing the execution times:
Note that these results are based on a single point-in-time result for each branch. For full results, see the dashboard. Graphs show the p99 interval based on the mean and StdDev of the test run, as well as the mean value of the run (shown as a diamond below the graph). Duration chartsFakeDbCommand (.NET Framework 4.8)gantt
title Execution time (ms) FakeDbCommand (.NET Framework 4.8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (72ms) : 70, 75
master - mean (73ms) : 70, 75
section Bailout
This PR (8674) - mean (79ms) : 75, 83
master - mean (79ms) : 75, 83
section CallTarget+Inlining+NGEN
This PR (8674) - mean (1,105ms) : 1059, 1152
master - mean (1,112ms) : 1046, 1178
FakeDbCommand (.NET Core 3.1)gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (116ms) : 109, 122
master - mean (117ms) : 112, 122
section Bailout
This PR (8674) - mean (118ms) : 113, 122
master - mean (116ms) : 111, 121
section CallTarget+Inlining+NGEN
This PR (8674) - mean (794ms) : 770, 818
master - mean (792ms) : 767, 816
FakeDbCommand (.NET 6)gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (102ms) : 97, 108
master - mean (102ms) : 98, 106
section Bailout
This PR (8674) - mean (102ms) : 99, 104
master - mean (106ms) : 101, 111
section CallTarget+Inlining+NGEN
This PR (8674) - mean (947ms) : 910, 983
master - mean (946ms) : 912, 980
FakeDbCommand (.NET 8)gantt
title Execution time (ms) FakeDbCommand (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (102ms) : 96, 108
master - mean (99ms) : 96, 102
section Bailout
This PR (8674) - mean (103ms) : 98, 108
master - mean (100ms) : 98, 102
section CallTarget+Inlining+NGEN
This PR (8674) - mean (824ms) : 784, 864
master - mean (826ms) : 786, 865
HttpMessageHandler (.NET Framework 4.8)gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (199ms) : 194, 203
master - mean (199ms) : 193, 205
section Bailout
This PR (8674) - mean (202ms) : 197, 206
master - mean (202ms) : 196, 208
section CallTarget+Inlining+NGEN
This PR (8674) - mean (1,198ms) : 1151, 1244
master - mean (1,203ms) : 1149, 1256
HttpMessageHandler (.NET Core 3.1)gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (288ms) : 281, 294
master - mean (285ms) : 277, 293
section Bailout
This PR (8674) - mean (287ms) : 281, 293
master - mean (286ms) : 277, 294
section CallTarget+Inlining+NGEN
This PR (8674) - mean (962ms) : 940, 983
master - mean (961ms) : 939, 983
HttpMessageHandler (.NET 6)gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (276ms) : 268, 285
master - mean (278ms) : 271, 285
section Bailout
This PR (8674) - mean (276ms) : 268, 284
master - mean (279ms) : 274, 284
section CallTarget+Inlining+NGEN
This PR (8674) - mean (1,161ms) : 1125, 1198
master - mean (1,155ms) : 1122, 1188
HttpMessageHandler (.NET 8)gantt
title Execution time (ms) HttpMessageHandler (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8674) - mean (275ms) : 269, 282
master - mean (276ms) : 268, 283
section Bailout
This PR (8674) - mean (275ms) : 267, 284
master - mean (277ms) : 271, 282
section CallTarget+Inlining+NGEN
This PR (8674) - mean (1,036ms) : 999, 1073
master - mean (1,036ms) : 996, 1076
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
andrewlock
reviewed
May 26, 2026
| && activityTraceId is not null | ||
| && Tracer.Instance.ActiveScope?.Span is Span activeSpan | ||
| && (activity.Parent is null || activity.Parent.StartTimeUtc <= activeSpan.StartTime.UtcDateTime)) | ||
| && (activity.Parent is null || activity.Parent.StartTimeUtc <= activeSpan.StartTime.UtcDateTime + ParentReorderingClockSkewTolerance)) |
Member
There was a problem hiding this comment.
This kind of makes me question whether this start time heuristic is correct at all? 🤔 @zacharycmontoya @bouwkast any thoughts?
Contributor
There was a problem hiding this comment.
Suspicious 🤔 So the goal of this block is to make sure that we "reparent" an Activity to the currently active one if it makes sense. There's two cases here:
Activity.Parent is nullaka a root spanActivity.Parentis not null
For the root span case, the remote case is already handled, so this remaps the Activity so its parent points to an existing Datadog span. That's fine, though I'm thinking we may have a separate issue, but that's irrelevant for now... 😅
For the non-root span case, the timing check is supposed to ensure we're keeping the stack of .NET Activity / Datadog spans in the proper order. When there are no clock issues, this usually results in a .NET Activity, followed by a Datadog span representing that .NET Activity, followed by 0+ newer Datadog spans, followed by the next .NET Activity (presumably this invocation).
In that sense, the timing check kinda works to make sure that we always rewrite an Activity so its parent span ID becomes the span ID of the latest Datadog span. I think this still makes sense for our current shadow stack of Datadog spans. If we find ways to optimize this and no longer keep two separate stacks, that would be a good time to reconsider this timing check
Collaborator
There was a problem hiding this comment.
FWIW (I think) this came up as a bug a while back and speaking with Tony it basically was that there wasn't a great way to reconcile this at the moment as we have two different time sources
Collaborator
Author
There was a problem hiding this comment.
So I guess that we could either:
- Merge the timing tolerance value workaround
or - Mark underlying tests as flaky.
The problem of marking the tests as flaky is that the issue is real.
WDYT?
Member
There was a problem hiding this comment.
I agree, this very much seems like a "real" issue to me, what's not entirely clear to me is whether this causes any other flake the other way 😅 I'll defer to the others, but I think this is probably fine based on the answers above
Contributor
There was a problem hiding this comment.
I vote for merging the timing tolerance workaround
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary of changes
Add a 50 ms tolerance to the Activity → Span reparenting time check in
ActivityHandlerCommon.Reason for change
SimpleActivitiesAndSpansTestflaked on master (build 202056) because the reparenting heuristic compares two different clock sources:Activity.StartTimeUtc—DateTime.UtcNow(system clock)Span.StartTime—TraceClock.UtcNow(Stopwatch-based, recalibrated againstDateTime.UtcNowonly every 5 min, with up to 16 ms calibration slack)These can drift apart, so an
Activitystarted a few µs before aSpancan still end up withParent.StartTimeUtc > activeSpan.StartTime, causing the<=guard to fail and reparenting to silently skip. In #5735 the same guard was relaxed from<to<=to handle low-resolution clocks on macOS — that fix doesn't cover the drift case where the parent time is strictly greater than the child.The customer-visible impact of skipping reparenting is the same as the test symptom: an OTel child
Activitycreated right after a DDSpankeeps its original W3C parent instead of being linked to the DD span, breaking trace continuity.Implementation details
Added
ParentReorderingClockSkewTolerance = 50 msand changed the guard fromactivity.Parent.StartTimeUtc <= activeSpan.StartTime.UtcDateTimeto
activity.Parent.StartTimeUtc <= activeSpan.StartTime.UtcDateTime + ParentReorderingClockSkewTolerance.50 ms comfortably covers TraceClock's 16 ms calibration slack plus typical NTP step adjustments, while still being well under any realistic causal gap between unrelated spans in a single async chain.
Test coverage
Existing
ActivityTests.SimpleActivitiesAndSpansTestexercises this path; the change makes that test stable on Windows where the drift was observed.Other details