Correctly set `activityKey` when we change the Trace ID #5771

bouwkast · 2024-07-03T15:19:46Z

Summary of changes

This delays the computation of activityKey (used to map an Activity to a Datadog Scope) by it's TraceID + SpanID to be after we could potentially modify those values.

Reason for change

We do modify the TraceId of an Activity. The previous way would cause MISSING SCOPE logs as we'd use the outdated Trace Id when searching for the mapping.

Implementation details

Move setting of activityKey later
Update activityTraceId when we change the Activity's TraceId

Test coverage

Had to update the OpenTelemetryTests as they weren't correct

Other details

github-actions · 2024-07-03T15:20:34Z

Snapshots difference summary

The following differences have been observed in committed snapshots. It is meant to help the reviewer.
The diff is simplistic, so please check some files anyway while we improve it.

3 occurrences of :

-    Service: CustomServiceName,
+    Service: MyServiceName,

3 occurrences of :

-      runtime-id: Guid_2,
+      service.instance.id: Guid_3,
+      service.name: MyServiceName,
+      service.version: 1.0.x,
[...]
-      version: 1.0.x
-    },
-    Metrics: {
-      _dd.top_level: 1.0
+      telemetry.sdk.language: dotnet,
+      telemetry.sdk.name: opentelemetry,
+      telemetry.sdk.version: sdk-version,
+      _dd.base_service: CustomServiceName

bouwkast · 2024-07-03T15:21:30Z

I think this has been an issue for a while 😬

datadog-ddstaging · 2024-07-03T15:44:18Z

Datadog Report

Branch report: steven/activity-key-fix
Commit report: c66e302
Test service: dd-trace-dotnet

✅ 0 Failed, 346482 Passed, 1763 Skipped, 14h 26m 11.07s Total Time

andrewlock · 2024-07-03T16:11:34Z

Execution-Time Benchmarks Report ⏱️

Execution-time results for samples comparing the following branches/commits:

Execution-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 shown in red. The following thresholds were used for comparing the execution times:

Welch test with statistical test for significance of 5%
Only results indicating a difference greater than 5% and 5 ms are considered.

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).

gantt
    title Execution time (ms) FakeDbCommand (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5771) - mean (71ms)  : 64, 78
     .   : milestone, 71,
    master - mean (73ms)  : 63, 82
     .   : milestone, 73,

    section CallTarget+Inlining+NGEN
    This PR (5771) - mean (1,048ms)  : 1033, 1064
     .   : milestone, 1048,
    master - mean (1,046ms)  : 1029, 1064
     .   : milestone, 1046,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5771) - mean (108ms)  : 105, 111
     .   : milestone, 108,
    master - mean (108ms)  : 104, 112
     .   : milestone, 108,

    section CallTarget+Inlining+NGEN
    This PR (5771) - mean (745ms)  : 724, 767
     .   : milestone, 745,
    master - mean (748ms)  : 729, 766
     .   : milestone, 748,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5771) - mean (92ms)  : 89, 94
     .   : milestone, 92,
    master - mean (92ms)  : 88, 96
     .   : milestone, 92,

    section CallTarget+Inlining+NGEN
    This PR (5771) - mean (703ms)  : 684, 722
     .   : milestone, 703,
    master - mean (701ms)  : 679, 722
     .   : milestone, 701,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5771) - mean (195ms)  : 188, 201
     .   : milestone, 195,
    master - mean (191ms)  : 189, 194
     .   : milestone, 191,

    section CallTarget+Inlining+NGEN
    This PR (5771) - mean (1,195ms)  : 1166, 1223
     .   : milestone, 1195,
    master - mean (1,179ms)  : 1153, 1204
     .   : milestone, 1179,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5771) - mean (279ms)  : 273, 285
     .   : milestone, 279,
    master - mean (275ms)  : 270, 280
     .   : milestone, 275,

    section CallTarget+Inlining+NGEN
    This PR (5771) - mean (970ms)  : 948, 993
     .   : milestone, 970,
    master - mean (970ms)  : 942, 998
     .   : milestone, 970,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5771) - mean (272ms)  : 264, 279
     .   : milestone, 272,
    master - mean (264ms)  : 260, 268
     .   : milestone, 264,

    section CallTarget+Inlining+NGEN
    This PR (5771) - mean (959ms)  : 931, 987
     .   : milestone, 959,
    master - mean (946ms)  : 922, 970
     .   : milestone, 946,

andrewlock

Nice catch 👍

andrewlock · 2024-07-03T21:27:23Z

Benchmarks Report for tracer 🐌

Benchmarks for #5771 compared to master:

1 benchmarks are faster, with geometric mean 1.173
1 benchmarks have fewer allocations

The following thresholds were used for comparing the benchmark speeds:

Mann–Whitney U test with statistical test for significance of 5%
Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`StartStopWithChild`	net6.0	7.72μs	44.2ns	319ns	0.0148	0.00741	0	5.43 KB
master	`StartStopWithChild`	netcoreapp3.1	10.1μs	55.5ns	324ns	0.0201	0.00502	0	5.62 KB
master	`StartStopWithChild`	net472	16.9μs	79.8ns	319ns	1.02	0.301	0.0919	6.06 KB
#5771	`StartStopWithChild`	net6.0	7.64μs	41.5ns	262ns	0.0113	0.00376	0	5.43 KB
#5771	`StartStopWithChild`	netcoreapp3.1	10.1μs	53.2ns	286ns	0.0195	0.00976	0	5.62 KB
#5771	`StartStopWithChild`	net472	17.2μs	46.9ns	182ns	1.03	0.317	0.0942	6.06 KB

Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	496μs	189ns	730ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	619μs	150ns	581ns	0	2.7 KB
master	`WriteAndFlushEnrichedTraces`	net472	829μs	536ns	2.08μs	0.417	3.3 KB
#5771	`WriteAndFlushEnrichedTraces`	net6.0	483μs	197ns	736ns	0	2.7 KB
#5771	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	625μs	487ns	1.89μs	0	2.7 KB
#5771	`WriteAndFlushEnrichedTraces`	net472	826μs	294ns	1.14μs	0.411	3.3 KB

Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendRequest`	net6.0	173μs	212ns	822ns	0.256	18.45 KB
master	`SendRequest`	netcoreapp3.1	191μs	339ns	1.31μs	0.191	20.61 KB
master	`SendRequest`	net472	0.00146ns	0.000266ns	0.000995ns	0	0 b
#5771	`SendRequest`	net6.0	171μs	117ns	438ns	0.172	18.45 KB
#5771	`SendRequest`	netcoreapp3.1	192μs	139ns	502ns	0.194	20.61 KB
#5771	`SendRequest`	net472	0.000878ns	0.000256ns	0.000991ns	0	0 b

Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Fewer allocations 🎉

Fewer allocations 🎉 in #5771

Benchmark	Base Allocated	Diff Allocated	Change	Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1	41.8 KB	41.57 KB	-226 B	-0.54%

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Gen 2	Allocated
master	`WriteAndFlushEnrichedTraces`	net6.0	544μs	1.2μs	4.65μs	0.543	0	0	41.55 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	655μs	966ns	3.74μs	0.327	0	0	41.8 KB
master	`WriteAndFlushEnrichedTraces`	net472	873μs	3.85μs	14.9μs	8.39	2.52	0.419	53.26 KB
#5771	`WriteAndFlushEnrichedTraces`	net6.0	543μs	319ns	1.23μs	0.536	0	0	41.59 KB
#5771	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	666μs	1.27μs	4.93μs	0.332	0	0	41.57 KB
#5771	`WriteAndFlushEnrichedTraces`	net472	844μs	3.91μs	15.1μs	8.45	2.53	0.422	53.23 KB

Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteNonQuery`	net6.0	1.26μs	0.48ns	1.73ns	0.0145	1.02 KB
master	`ExecuteNonQuery`	netcoreapp3.1	1.71μs	0.975ns	3.78ns	0.0137	1.02 KB
master	`ExecuteNonQuery`	net472	1.95μs	1.51ns	5.44ns	0.156	987 B
#5771	`ExecuteNonQuery`	net6.0	1.21μs	0.437ns	1.69ns	0.0141	1.02 KB
#5771	`ExecuteNonQuery`	netcoreapp3.1	1.67μs	0.811ns	3.14ns	0.0134	1.02 KB
#5771	`ExecuteNonQuery`	net472	2.01μs	0.586ns	2.11ns	0.156	987 B

Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`CallElasticsearch`	net6.0	1.2μs	4.63ns	17.9ns	0.0136	0	976 B
master	`CallElasticsearch`	netcoreapp3.1	1.55μs	0.865ns	3.24ns	0.0134	0	976 B
master	`CallElasticsearch`	net472	2.5μs	1.33ns	4.97ns	0.158	0.00125	995 B
master	`CallElasticsearchAsync`	net6.0	1.32μs	0.565ns	2.12ns	0.0133	0	952 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.7μs	0.922ns	3.57ns	0.0136	0	1.02 KB
master	`CallElasticsearchAsync`	net472	2.65μs	2.33ns	9.01ns	0.166	0.00133	1.05 KB
#5771	`CallElasticsearch`	net6.0	1.23μs	2.89ns	11.2ns	0.014	0	976 B
#5771	`CallElasticsearch`	netcoreapp3.1	1.48μs	0.921ns	3.57ns	0.0133	0	976 B
#5771	`CallElasticsearch`	net472	2.58μs	1.45ns	5.62ns	0.157	0.00129	995 B
#5771	`CallElasticsearchAsync`	net6.0	1.29μs	1.4ns	5.41ns	0.0129	0	952 B
#5771	`CallElasticsearchAsync`	netcoreapp3.1	1.61μs	0.816ns	3.05ns	0.0137	0	1.02 KB
#5771	`CallElasticsearchAsync`	net472	2.68μs	1.39ns	5.22ns	0.167	0.00133	1.05 KB

Benchmarks.Trace.GraphQLBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #5771

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0	1.173	1,339.53	1,142.14

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteAsync`	net6.0	1.34μs	0.929ns	3.6ns	0.0135	0	952 B
master	`ExecuteAsync`	netcoreapp3.1	1.57μs	0.712ns	2.76ns	0.0128	0	952 B
master	`ExecuteAsync`	net472	1.75μs	0.778ns	2.91ns	0.145	0	915 B
#5771	`ExecuteAsync`	net6.0	1.15μs	3.79ns	17.8ns	0.0132	0	952 B
#5771	`ExecuteAsync`	netcoreapp3.1	1.55μs	0.517ns	1.87ns	0.0125	0	952 B
#5771	`ExecuteAsync`	net472	1.88μs	1.5ns	5.81ns	0.145	0.000879	915 B

Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendAsync`	net6.0	4.11μs	1.45ns	5.63ns	0.0307	2.22 KB
master	`SendAsync`	netcoreapp3.1	5.03μs	1.81ns	7ns	0.0376	2.76 KB
master	`SendAsync`	net472	7.59μs	2.11ns	8.16ns	0.499	3.15 KB
#5771	`SendAsync`	net6.0	4.11μs	2.11ns	7.88ns	0.031	2.22 KB
#5771	`SendAsync`	netcoreapp3.1	5.03μs	2.07ns	8.02ns	0.0376	2.76 KB
#5771	`SendAsync`	net472	7.68μs	2.44ns	9.15ns	0.498	3.15 KB

Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	1.52μs	0.826ns	3.09ns	0.0229	1.64 KB
master	`EnrichedLog`	netcoreapp3.1	2.13μs	1.09ns	4.23ns	0.0225	1.64 KB
master	`EnrichedLog`	net472	2.46μs	1.6ns	5.76ns	0.249	1.57 KB
#5771	`EnrichedLog`	net6.0	1.5μs	0.467ns	1.68ns	0.0234	1.64 KB
#5771	`EnrichedLog`	netcoreapp3.1	2.29μs	1.06ns	3.95ns	0.0216	1.64 KB
#5771	`EnrichedLog`	net472	2.51μs	0.99ns	3.7ns	0.25	1.57 KB

Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net6.0	115μs	203ns	785ns	0.0579	0	4.28 KB
master	`EnrichedLog`	netcoreapp3.1	118μs	141ns	527ns	0.0592	0	4.28 KB
master	`EnrichedLog`	net472	149μs	192ns	745ns	0.665	0.222	4.46 KB
#5771	`EnrichedLog`	net6.0	115μs	146ns	567ns	0.0578	0	4.28 KB
#5771	`EnrichedLog`	netcoreapp3.1	119μs	177ns	661ns	0	0	4.28 KB
#5771	`EnrichedLog`	net472	148μs	160ns	597ns	0.664	0.221	4.46 KB

Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.83μs	0.637ns	2.38ns	0.0311	2.2 KB
master	`EnrichedLog`	netcoreapp3.1	4.19μs	1.69ns	5.85ns	0.0293	2.2 KB
master	`EnrichedLog`	net472	4.96μs	2.63ns	10.2ns	0.32	2.02 KB
#5771	`EnrichedLog`	net6.0	2.8μs	1.14ns	4.41ns	0.0307	2.2 KB
#5771	`EnrichedLog`	netcoreapp3.1	4.15μs	1.3ns	4.67ns	0.0291	2.2 KB
#5771	`EnrichedLog`	net472	5.03μs	2.89ns	11.2ns	0.319	2.02 KB

Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendReceive`	net6.0	1.33μs	0.793ns	3.07ns	0.016	0	1.14 KB
master	`SendReceive`	netcoreapp3.1	1.7μs	0.97ns	3.76ns	0.0152	0	1.14 KB
master	`SendReceive`	net472	2.08μs	2.48ns	9.59ns	0.183	0.00103	1.16 KB
#5771	`SendReceive`	net6.0	1.35μs	0.777ns	3.01ns	0.0157	0	1.14 KB
#5771	`SendReceive`	netcoreapp3.1	1.7μs	2.04ns	7.89ns	0.0153	0	1.14 KB
#5771	`SendReceive`	net472	2.04μs	1.88ns	7.28ns	0.183	0.00102	1.16 KB

Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net6.0	2.62μs	0.859ns	3.33ns	0.0223	1.6 KB
master	`EnrichedLog`	netcoreapp3.1	3.91μs	2.25ns	8.71ns	0.0217	1.65 KB
master	`EnrichedLog`	net472	4.34μs	2.38ns	9.23ns	0.323	2.04 KB
#5771	`EnrichedLog`	net6.0	2.8μs	0.976ns	3.78ns	0.0226	1.6 KB
#5771	`EnrichedLog`	netcoreapp3.1	3.84μs	2.44ns	9.47ns	0.0212	1.65 KB
#5771	`EnrichedLog`	net472	4.44μs	2.6ns	10.1ns	0.322	2.04 KB

Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net6.0	401ns	0.0919ns	0.356ns	0.00806	576 B
master	`StartFinishSpan`	netcoreapp3.1	659ns	0.657ns	2.54ns	0.00794	576 B
master	`StartFinishSpan`	net472	663ns	0.63ns	2.44ns	0.0918	578 B
master	`StartFinishScope`	net6.0	539ns	0.217ns	0.84ns	0.00973	696 B
master	`StartFinishScope`	netcoreapp3.1	714ns	0.314ns	1.17ns	0.00931	696 B
master	`StartFinishScope`	net472	929ns	0.334ns	1.29ns	0.104	658 B
#5771	`StartFinishSpan`	net6.0	396ns	0.169ns	0.655ns	0.00798	576 B
#5771	`StartFinishSpan`	netcoreapp3.1	604ns	0.458ns	1.77ns	0.00765	576 B
#5771	`StartFinishSpan`	net472	645ns	0.42ns	1.63ns	0.0917	578 B
#5771	`StartFinishScope`	net6.0	583ns	0.194ns	0.751ns	0.00975	696 B
#5771	`StartFinishScope`	netcoreapp3.1	677ns	0.468ns	1.69ns	0.00925	696 B
#5771	`StartFinishScope`	net472	917ns	0.665ns	2.57ns	0.104	658 B

Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net6.0	665ns	0.272ns	1.05ns	0.00968	696 B
master	`RunOnMethodBegin`	netcoreapp3.1	951ns	0.514ns	1.99ns	0.00951	696 B
master	`RunOnMethodBegin`	net472	1.1μs	0.494ns	1.91ns	0.104	658 B
#5771	`RunOnMethodBegin`	net6.0	730ns	0.173ns	0.624ns	0.00984	696 B
#5771	`RunOnMethodBegin`	netcoreapp3.1	970ns	0.415ns	1.61ns	0.0092	696 B
#5771	`RunOnMethodBegin`	net472	1.1μs	0.533ns	2.06ns	0.104	658 B

bouwkast requested a review from a team as a code owner July 3, 2024 15:19

lucaspimentel approved these changes Jul 3, 2024

View reviewed changes

andrewlock approved these changes Jul 3, 2024

View reviewed changes

Correctly set activityKey

c66e302

bouwkast force-pushed the steven/activity-key-fix branch from 7b9219a to c66e302 Compare July 10, 2024 15:02

bouwkast merged commit 92da68e into master Jul 10, 2024
55 of 57 checks passed

bouwkast deleted the steven/activity-key-fix branch July 10, 2024 19:08

github-actions bot added this to the vNext-v2 milestone Jul 10, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Correctly set `activityKey` when we change the Trace ID #5771

Correctly set `activityKey` when we change the Trace ID #5771

bouwkast commented Jul 3, 2024

github-actions bot commented Jul 3, 2024

bouwkast commented Jul 3, 2024

datadog-ddstaging bot commented Jul 3, 2024 •

edited

Loading

andrewlock commented Jul 3, 2024 •

edited

Loading

andrewlock left a comment

andrewlock commented Jul 3, 2024 •

edited

Loading

Raw results

Raw results

Raw results

Fewer allocations 🎉 in #5771

Raw results

Raw results

Raw results

Faster 🎉 in #5771

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Correctly set activityKey when we change the Trace ID #5771

Correctly set activityKey when we change the Trace ID #5771

Conversation

bouwkast commented Jul 3, 2024

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

github-actions bot commented Jul 3, 2024

Snapshots difference summary

bouwkast commented Jul 3, 2024

datadog-ddstaging bot commented Jul 3, 2024 • edited Loading

Datadog Report

andrewlock commented Jul 3, 2024 • edited Loading

Execution-Time Benchmarks Report ⏱️

andrewlock left a comment

Choose a reason for hiding this comment

andrewlock commented Jul 3, 2024 • edited Loading

Benchmarks Report for tracer 🐌

Benchmark details

Raw results

Raw results

Raw results

Fewer allocations 🎉 in #5771

Raw results

Raw results

Raw results

Faster 🎉 in #5771

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Correctly set `activityKey` when we change the Trace ID #5771

Correctly set `activityKey` when we change the Trace ID #5771

datadog-ddstaging bot commented Jul 3, 2024 •

edited

Loading

andrewlock commented Jul 3, 2024 •

edited

Loading

andrewlock commented Jul 3, 2024 •

edited

Loading