dd-trace-dotnet icon indicating copy to clipboard operation
dd-trace-dotnet copied to clipboard
verified publisher icon DataDog

Correctly set `activityKey` when we change the Trace ID

Open bouwkast opened this issue 1 year ago • 5 comments

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

bouwkast avatar Jul 03 '24 15:07 bouwkast

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

github-actions[bot] avatar Jul 03 '24 15:07 github-actions[bot]

I think this has been an issue for a while 😬

bouwkast avatar Jul 03 '24 15:07 bouwkast

Datadog Report

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

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

datadog-ddstaging[bot] avatar Jul 03 '24 15:07 datadog-ddstaging[bot]

Execution-Time Benchmarks Report :stopwatch:

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 avatar Jul 03 '24 16:07 andrewlock

Benchmarks Report for tracer :snail:

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 :heavy_check_mark: Same allocations :heavy_check_mark:

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 :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

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

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 173μs 212ns 822ns 0.256 0 0 18.45 KB
master SendRequest netcoreapp3.1 191μs 339ns 1.31μs 0.191 0 0 20.61 KB
master SendRequest net472 0.00146ns 0.000266ns 0.000995ns 0 0 0 0 b
#5771 SendRequest net6.0 171μs 117ns 438ns 0.172 0 0 18.45 KB
#5771 SendRequest netcoreapp3.1 192μs 139ns 502ns 0.194 0 0 20.61 KB
#5771 SendRequest net472 0.000878ns 0.000256ns 0.000991ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed :heavy_check_mark: Fewer allocations :tada:

Fewer allocations :tada: 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 :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

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

Raw results

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

Faster :tada: 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 Gen 2 Allocated
master ExecuteAsync net6.0 1.34μs 0.929ns 3.6ns 0.0135 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.57μs 0.712ns 2.76ns 0.0128 0 0 952 B
master ExecuteAsync net472 1.75μs 0.778ns 2.91ns 0.145 0 0 915 B
#5771 ExecuteAsync net6.0 1.15μs 3.79ns 17.8ns 0.0132 0 0 952 B
#5771 ExecuteAsync netcoreapp3.1 1.55μs 0.517ns 1.87ns 0.0125 0 0 952 B
#5771 ExecuteAsync net472 1.88μs 1.5ns 5.81ns 0.145 0.000879 0 915 B
Benchmarks.Trace.HttpClientBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

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

Raw results

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

Raw results

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

Raw results

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

Raw results

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

Raw results

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

Raw results

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

Raw results

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

andrewlock avatar Jul 03 '24 21:07 andrewlock