Switch Activity handling to use WeakReference<T>#8549
Conversation
| try | ||
| { | ||
| if (activity.Instance is not null) | ||
| if (activity.Instance is null) |
There was a problem hiding this comment.
The bulk of this method is just whitespace changes, just changed to early return
| return; | ||
| } | ||
|
|
||
| StopActivitySlow(sourceName, activity); |
There was a problem hiding this comment.
This doesn't happen here now, happens in reconciliation loop
| return new ReconciliationSweepResult(gcCollected, missedStop, iterated); | ||
| } | ||
|
|
||
| private static void CloseActivityScope<TInner>(TInner activity, Scope scope) |
There was a problem hiding this comment.
This hasn't changed, just made it a method instead of local function for reuse
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 20e01202c0
ℹ️ About Codex in GitHub
Your team has set up Codex to 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 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
| // No matching entry — either Start was never observed, or the periodic | ||
| // reconciliation sweep already cleaned this one up. Nothing to do here. | ||
| if (Log.IsEnabled(LogEventLevel.Information)) | ||
| { | ||
| Log.Information("DefaultActivityHandler.ActivityStopped: MISSING SCOPE [Source={SourceName}, Id={Id}, RootId={RootId}, OperationName={OperationName}, StartTimeUtc={StartTimeUtc}, Duration={Duration}]", new object[] { sourceName, activity.Id, activity.RootId, activity.OperationName!, activity.StartTimeUtc, activity.Duration }); |
There was a problem hiding this comment.
Restore same-context cleanup on missed Activity stops
When a Stop callback arrives for an Activity whose exact key lookup misses, this now only logs and relies on the timer-based reconciliation. For the key-mismatch cases that the previous StopActivitySlow handled, the Datadog scope is still active in the caller's AsyncLocal context; the later timer sweep runs in a different ExecutionContext, and AsyncLocalScopeManager.Close() will not clear that original active scope. This can leave subsequent spans in the same request parented to the stale Activity span even after the sweep finishes/removes it.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
If we don't have a lookup key, I'm not sure that this is going to be the case. Right now, as I understand it, we don't have a good scenario where we expect to hit this, and doing the reconciliation in this hot path has performance impacts I believe 🤔
| if (activity6.Duration != TimeSpan.Zero | ||
| && mappings.TryRemove(kvp.Key, out var owned) | ||
| && owned.Scope is { } scope) | ||
| { | ||
| if (activity4.Duration != TimeSpan.Zero) | ||
| { | ||
| CloseActivityScope(sourceName, activity4, scope); | ||
| hasClosed = true; | ||
| } | ||
| CloseActivityScope(activity6, scope); |
There was a problem hiding this comment.
Avoid treating SetEndTime as a missed Stop
The new sweep is periodic, so Duration != TimeSpan.Zero is no longer only evaluated while handling a Stop callback. Activity.SetEndTime() sets Duration without stopping the Activity, so a live Activity that sets an end time and continues for more than ReconciliationInterval will be removed and finished here before its actual Stop callback, dropping tags/events added afterward and making the real Stop report a missing scope. Use an actual stopped signal where available, or avoid sweeping live entries based only on Duration.
Useful? React with 👍 / 👎.
zacharycmontoya
left a comment
There was a problem hiding this comment.
LGTM, and great tests!
Execution-Time Benchmarks Report ⏱️Execution-time results for samples comparing This PR (8549) 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 (8549) - mean (73ms) : 71, 75
master - mean (73ms) : 70, 76
section Bailout
This PR (8549) - mean (79ms) : 76, 82
master - mean (77ms) : 76, 79
section CallTarget+Inlining+NGEN
This PR (8549) - mean (1,079ms) : 1040, 1118
master - mean (1,072ms) : 1029, 1116
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 (8549) - mean (114ms) : 110, 117
master - mean (116ms) : 110, 123
section Bailout
This PR (8549) - mean (119ms) : 113, 124
master - mean (116ms) : 113, 119
section CallTarget+Inlining+NGEN
This PR (8549) - mean (775ms) : 750, 800
master - mean (783ms) : 755, 810
FakeDbCommand (.NET 6)gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8549) - mean (101ms) : 97, 105
master - mean (103ms) : 97, 109
section Bailout
This PR (8549) - mean (103ms) : 98, 107
master - mean (105ms) : 99, 111
section CallTarget+Inlining+NGEN
This PR (8549) - mean (935ms) : 900, 971
master - mean (940ms) : 898, 983
FakeDbCommand (.NET 8)gantt
title Execution time (ms) FakeDbCommand (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8549) - mean (104ms) : 99, 109
master - mean (101ms) : 97, 104
section Bailout
This PR (8549) - mean (102ms) : 99, 105
master - mean (104ms) : 99, 110
section CallTarget+Inlining+NGEN
This PR (8549) - mean (824ms) : 788, 861
master - mean (823ms) : 788, 857
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 (8549) - mean (203ms) : 196, 210
master - mean (205ms) : 199, 211
section Bailout
This PR (8549) - mean (207ms) : 198, 215
master - mean (212ms) : 204, 220
section CallTarget+Inlining+NGEN
This PR (8549) - mean (1,214ms) : 1154, 1273
master - mean (1,218ms) : 1156, 1280
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 (8549) - mean (296ms) : 284, 309
master - mean (298ms) : 287, 308
section Bailout
This PR (8549) - mean (297ms) : 283, 310
master - mean (299ms) : 287, 311
section CallTarget+Inlining+NGEN
This PR (8549) - mean (982ms) : 954, 1010
master - mean (972ms) : 943, 1000
HttpMessageHandler (.NET 6)gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8549) - mean (290ms) : 278, 301
master - mean (289ms) : 278, 300
section Bailout
This PR (8549) - mean (291ms) : 279, 303
master - mean (289ms) : 278, 300
section CallTarget+Inlining+NGEN
This PR (8549) - mean (1,168ms) : 1125, 1211
master - mean (1,165ms) : 1127, 1203
HttpMessageHandler (.NET 8)gantt
title Execution time (ms) HttpMessageHandler (.NET 8)
dateFormat x
axisFormat %Q
todayMarker off
section Baseline
This PR (8549) - mean (289ms) : 277, 302
master - mean (288ms) : 271, 306
section Bailout
This PR (8549) - mean (287ms) : 277, 297
master - mean (288ms) : 273, 302
section CallTarget+Inlining+NGEN
This PR (8549) - mean (1,047ms) : 998, 1097
master - mean (1,063ms) : 983, 1143
|
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
| } | ||
| } | ||
|
|
||
| span.SetTag("closed_reason", "garbage_collected"); |
There was a problem hiding this comment.
The PR description mentions "is_incomplete=true". Do we set that tag?
There was a problem hiding this comment.
Ah, we changed that based on feedback 🙂 Will update the description!
| // Activity is still alive. A non-zero Duration on an entry that's still in | ||
| // the dictionary means Stop() was called but our listener callback didn't | ||
| // handle it — close it using the real end time. | ||
| if (activityObject.TryDuckCast<IActivity6>(out var activity6)) |
There was a problem hiding this comment.
Should we add a close_reason for these cases too?
There was a problem hiding this comment.
I'm not sure, but I don't think so 🤔 We added the close_reason to the other one because it technically "shouldn't" have been closed, whereas these should be closed, and they're closed "correctly", unlike the other ones. I think adding close_reason here could be more confusing than anything else 🤔 Also, we currently have this code path today (we just run it much more often), and didn't see the need for the tag before. But I'm not sure, WDYT @zacharycmontoya?
NachoEchevarria
left a comment
There was a problem hiding this comment.
Very nice! Thanks!
BenchmarksBenchmark execution time: 2026-05-06 11:20:21 Comparing candidate commit aa87116 in PR branch Found 0 performance improvements and 0 performance regressions! Performance is the same for 27 metrics, 0 unstable metrics, 59 known flaky benchmarks, 28 flaky benchmarks without significant changes.
|
…OTel (#8576) ## Summary of changes Don't auto-close closed-`Activity` related `Scope` which have been closed for < 1 minute ## Reason for change In #8549, we moved the "CloseActivitySlow" reconciliation step when an `Activity` is closed but we somehow "missed" the `StopActivity()` call into a background job. We don't have a known mechanism for how that would happen today, and so this seemed reasonable. There's a non-ideal aspect to this in terms of `AsyncLocal<T>` and execution context flow, in that we're now closing the `Scope` from a background task, that's _off_ the original `async` context that created it. This will theoretically mean that the `ActiveScope` flow doesn't work correctly (needs confirming, but it's plausible). This is _mostly_ "OK" given we don't have a known mechanism where we would hit this path _however_, we also introduced a race condition, where a given `Activity` is closed, and is in the _process_ of calling `StopActivity`, when our background loop executes. In that case we preemptively close it from the background thread. ## Implementation details As a workaround, this PR simply adds a 1 minute cutoff before we start closing the associated `Scope`, on the basis that this _should_ be plenty of time for our inline handler to run if it's going to. This isn't ideal, as it's somewhat of a hacky workaround, but then, so is the CloseActivitySlow process anyway 😅 The other option is that we move the reconciliation _back_ into the hot path, but that doesn't seem worth the trade off to me, especially as we consider this to be an unknown edge case anyway, and it's more there for safety than anything else. ## Test coverage Added a test to confirm that a "freshly" closed `Activity` is ignored, and it's only an "old" closed `Activity` that gets swept ## Other details Related to https://datadoghq.atlassian.net/browse/APMS-19316.
Summary of changes
Wraps the reference to
Activityin ourActivityHandlerCommonwith aWeakReference<T>to avoid leaking them if user's never stop theActivityReason for change
We have seen this happening in practice, and while it's a coding error, it manifests as a memory leak that's hard to diagnose without taking a memory dump.
This PR attempts to sidestep the issue by using
WeakReference, to avoid keeping anActivityalive for longer than it otherwise would. It then adds a "reconciliation" process that cleans up and removes anyActivityobject that is no longer reachable, and closes and finishes the correspondingSpan, so that we don't keep those around for ever (actually the bigger issue WRT memory leaks)Additionally, we already had an
StopActivitySlowprocess which was doing something similar, looping through the whole dictionary, trying to find any closedActivityinstances where theSpanwas still open. This was looping through every item in the dictionary, Every time a span was closed (which in the pathological case would be very slow), so this PR moves that to the reconciliation background task too).Implementation details
ActivityMappingto useWeakReference<object>for theActivityinstead ofobjectStartReconciliationLoopto have a process that loops the dictionary to look for missing references orActivityinstances which are stopped but for which we didn't close theSpan(shouldn't happen as I understand it)Span, set some basic properties to try to make them "sensible".SpanKind,OperationName,OtelStatusCode,ServiceName,ResourceName,Typeif not currently setclosed_reason=garbage_collectedto the span, so we/customers can identify spans like thisTest coverage
Also created a pathological app that creates (and never stops) an
Activity, and then hammer it in a loop