DataDog / dd-trace-dotnet

.NET Client Library for Datadog APM
https://docs.datadoghq.com/tracing/
Apache License 2.0
413 stars 132 forks source link

Do not reset `Activity.Id` for non-W3C formats #5739

Closed bouwkast closed 19 hours ago

bouwkast commented 1 week ago

Summary of changes

This makes it so that we validate that the Activity object is in W3C format (by checking that the Activity has a SpanID and TraceID after it stars) if we are updating the SpanId and TraceId.

Note that for this to happen the Activity needs to be a non-W3C format and it's start time must be less than the Datadog Active Span start time. This start time issue can happen as an Activity can modify its start time after it is started and we don't update the created Datadog span with that new information.

Reason for change

T fixes an edge case where an Activity object could be in a non-W3C format and hit this code resulting in its Id being erroneously set to null causing a NullReferenceException for us (workaround in #5690), but could have also thrown if anyone accessed that Id and attempted to make a call on it.

Implementation details

Check to ensure that the Activity is in W3C format - this is done by just checking that it already has a Span Id and Trace Id.

Test coverage

Added tests to Samples.NetActivitySdk, the RunManuallyUpdatedStartTime() would fail and throw an exception.

Other details

Should consider handling instances where users update the start time of the Activity and update the Datadog Span accordingly.

github-actions[bot] commented 1 week ago

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.

1 occurrences of :

+  },
+  {
+    TraceId: Id_60,
+    SpanId: Id_61,
+    Name: internal,
+    Resource: TimeParent,
+    Service: Samples.NetActivitySdk,
+    Type: custom,
+    Tags: {
+      env: integration_tests,
+      language: dotnet,
+      otel.status_code: STATUS_CODE_UNSET,
+      runtime-id: Guid_2,
+      span.kind: internal,
+      version: 1.0.0
+    },
+    Metrics: {
+      process_id: 0,
+      _dd.top_level: 1.0,
+      _dd.tracer_kr: 1.0,
+      _sampling_priority_v1: 1.0
+    }
+  },
+  {
+    TraceId: Id_60,
+    SpanId: Id_62,
+    Name: internal,
+    Resource: TimeTrigger,
+    Service: Samples.NetActivitySdk,
+    Type: custom,
+    ParentId: Id_61,
+    Tags: {
+      env: integration_tests,
+      language: dotnet,
+      otel.status_code: STATUS_CODE_UNSET,
+      span.kind: internal,
+      version: 1.0.0
+    }
+  },
+  {
+    TraceId: Id_60,
+    SpanId: Id_63,
+    Name: internal,
+    Resource: TimeChild,
+    Service: Samples.NetActivitySdk,
+    Type: custom,
+    ParentId: Id_62,
+    Tags: {
+      env: integration_tests,
+      language: dotnet,
+      otel.status_code: STATUS_CODE_UNSET,
+      span.kind: internal,
+      version: 1.0.0
+    }
datadog-ddstaging[bot] commented 1 week ago

Datadog Report

Branch report: steven/activity-null-id Commit report: 17eab6a Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 344820 Passed, 1649 Skipped, 14h 28m 18.03s Total Time :snowflake: 1 New Flaky

New Flaky Tests (1)

andrewlock commented 1 week ago

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:

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 (5739) - mean (72ms)  : 65, 80
     .   : milestone, 72,
    master - mean (74ms)  : 65, 83
     .   : milestone, 74,

    section CallTarget+Inlining+NGEN
    This PR (5739) - mean (990ms)  : 970, 1010
     .   : milestone, 990,
    master - mean (991ms)  : 973, 1009
     .   : milestone, 991,
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5739) - mean (109ms)  : 106, 112
     .   : milestone, 109,
    master - mean (110ms)  : 107, 113
     .   : milestone, 110,

    section CallTarget+Inlining+NGEN
    This PR (5739) - mean (703ms)  : 680, 725
     .   : milestone, 703,
    master - mean (698ms)  : 675, 722
     .   : milestone, 698,
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5739) - mean (92ms)  : 89, 96
     .   : milestone, 92,
    master - mean (93ms)  : 90, 96
     .   : milestone, 93,

    section CallTarget+Inlining+NGEN
    This PR (5739) - mean (654ms)  : 629, 679
     .   : milestone, 654,
    master - mean (657ms)  : 630, 683
     .   : milestone, 657,
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5739) - mean (193ms)  : 189, 198
     .   : milestone, 193,
    master - mean (192ms)  : 188, 196
     .   : milestone, 192,

    section CallTarget+Inlining+NGEN
    This PR (5739) - mean (1,098ms)  : 1075, 1121
     .   : milestone, 1098,
    master - mean (1,081ms)  : 1059, 1103
     .   : milestone, 1081,
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5739) - mean (278ms)  : 272, 284
     .   : milestone, 278,
    master - mean (276ms)  : 271, 281
     .   : milestone, 276,

    section CallTarget+Inlining+NGEN
    This PR (5739) - mean (886ms)  : 863, 910
     .   : milestone, 886,
    master - mean (874ms)  : 849, 899
     .   : milestone, 874,
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5739) - mean (267ms)  : 261, 272
     .   : milestone, 267,
    master - mean (269ms)  : 263, 275
     .   : milestone, 269,

    section CallTarget+Inlining+NGEN
    This PR (5739) - mean (862ms)  : 836, 889
     .   : milestone, 862,
    master - mean (867ms)  : 839, 894
     .   : milestone, 867,
andrewlock commented 1 week ago

Throughput/Crank Report:zap:

Throughput results for AspNetCoreSimpleController comparing the following branches/commits:

Cases where throughput results for the PR are worse than latest master (5% drop or greater), results are shown in red.

Note that these results are based on a single point-in-time result for each branch. For full results, see one of the many, many dashboards!

gantt
    title Throughput Linux x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5739) (12.154M)   : 0, 12153787
    master (11.753M)   : 0, 11753412
    benchmarks/2.9.0 (11.542M)   : 0, 11542126

    section Automatic
    This PR (5739) (8.187M)   : 0, 8187178
    master (7.853M)   : 0, 7853279
    benchmarks/2.9.0 (8.263M)   : 0, 8262905

    section Trace stats
    master (8.259M)   : 0, 8258966

    section Manual
    This PR (5739) (10.470M)   : 0, 10469997
    master (9.899M)   : 0, 9899401

    section Manual + Automatic
    This PR (5739) (7.672M)   : 0, 7672159
    master (7.433M)   : 0, 7432897

    section Version Conflict
    master (6.731M)   : 0, 6730574
gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5739) (9.545M)   : 0, 9545011
    master (9.574M)   : 0, 9574121
    benchmarks/2.9.0 (9.596M)   : 0, 9596140

    section Automatic
    This PR (5739) (6.558M)   : 0, 6558237
    master (6.671M)   : 0, 6671192

    section Trace stats
    master (6.990M)   : 0, 6990244

    section Manual
    This PR (5739) (8.382M)   : 0, 8381864
    master (8.307M)   : 0, 8306500

    section Manual + Automatic
    This PR (5739) (6.028M)   : 0, 6027873
    master (6.251M)   : 0, 6250704

    section Version Conflict
    master (5.762M)   : 0, 5761603
gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5739) (10.009M)   : 0, 10008907
    master (10.202M)   : 0, 10201759
    benchmarks/2.9.0 (10.213M)   : 0, 10213239

    section Automatic
    This PR (5739) (7.087M)   : 0, 7086987
    master (7.212M)   : 0, 7212394
    benchmarks/2.9.0 (7.482M)   : 0, 7482023

    section Trace stats
    master (7.549M)   : 0, 7549360

    section Manual
    This PR (5739) (8.691M)   : 0, 8691212
    master (9.013M)   : 0, 9012822

    section Manual + Automatic
    This PR (5739) (6.783M)   : 0, 6783486
    master (7.018M)   : 0, 7017920

    section Version Conflict
    master (6.365M)   : 0, 6365432
andrewlock commented 1 week ago

Benchmarks Report for tracer :snail:

Benchmarks for #5739 compared to master:

The following thresholds were used for comparing the benchmark speeds:

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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartStopWithChild`|net6.0|7.78μs|43.6ns|279ns|0.0154| 0.00768|0|5.42 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartStopWithChild`|netcoreapp3.1|9.78μs|52.8ns|280ns|0.0241| 0.00963|0|5.62 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartStopWithChild`|net472|16μs|49ns|190ns|1.01| 0.293|0.0952|6.07 KB| |#5739|`StartStopWithChild`|net6.0|7.63μs|40.7ns|211ns|0.0151| 0.00757|0|5.43 KB| |#5739|`StartStopWithChild`|netcoreapp3.1|9.99μs|53.5ns|293ns|0.0193| 0.00964|0|5.61 KB| |#5739|`StartStopWithChild`|net472|16μs|58.8ns|228ns|1.01| 0.303|0.0877|6.07 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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`WriteAndFlushEnrichedTraces`|net6.0|489μs|145ns|563ns|0| 0|0|2.7 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`WriteAndFlushEnrichedTraces`|netcoreapp3.1|640μs|294ns|1.14μs|0| 0|0|2.7 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`WriteAndFlushEnrichedTraces`|net472|838μs|306ns|1.19μs|0.414| 0|0|3.3 KB| |#5739|`WriteAndFlushEnrichedTraces`|net6.0|465μs|118ns|441ns|0| 0|0|2.7 KB| |#5739|`WriteAndFlushEnrichedTraces`|netcoreapp3.1|655μs|529ns|2.05μs|0| 0|0|2.7 KB| |#5739|`WriteAndFlushEnrichedTraces`|net472|830μs|151ns|565ns|0.414| 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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendRequest`|net6.0|170μs|229ns|886ns|0.168| 0|0|18.44 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendRequest`|netcoreapp3.1|191μs|299ns|1.16μs|0.192| 0|0|20.6 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendRequest`|net472|0.000295ns|0.000179ns|0.000692ns|0| 0|0|0 b| |#5739|`SendRequest`|net6.0|170μs|158ns|611ns|0.253| 0|0|18.44 KB| |#5739|`SendRequest`|netcoreapp3.1|193μs|315ns|1.22μs|0.191| 0|0|20.6 KB| |#5739|`SendRequest`|net472|0.000161ns|0.000119ns|0.000462ns|0| 0|0|0 b|
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - 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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`WriteAndFlushEnrichedTraces`|net6.0|547μs|312ns|1.12μs|0.543| 0|0|41.65 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`WriteAndFlushEnrichedTraces`|netcoreapp3.1|664μs|946ns|3.67μs|0.332| 0|0|41.89 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`WriteAndFlushEnrichedTraces`|net472|852μs|3.28μs|12.7μs|8.36| 2.64|0.44|53.25 KB| |#5739|`WriteAndFlushEnrichedTraces`|net6.0|533μs|244ns|912ns|0.539| 0|0|41.52 KB| |#5739|`WriteAndFlushEnrichedTraces`|netcoreapp3.1|653μs|1.53μs|5.93μs|0.327| 0|0|41.87 KB| |#5739|`WriteAndFlushEnrichedTraces`|net472|858μs|2.95μs|11μs|8.28| 2.48|0.414|53.26 KB|
Benchmarks.Trace.DbCommandBenchmark - Slower :warning: Same allocations :heavy_check_mark: #### Slower :warning: in #5739 | Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality | |:----------|-----------:|-----------:|--------:|--------:| | Benchmarks.Trace.DbCommandBenchmark.ExecuteNonQuery‑net6.0 | 1.121 | 1,000.09 | 1,120.73 | ### Raw results | Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated | |---------|---------------------------- |-------------- |---------:|---------:|--------:|-------:|------:|------:|----------:| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`ExecuteNonQuery`|net6.0|1μs|0.463ns|1.79ns|0.011| 0|0|808 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`ExecuteNonQuery`|netcoreapp3.1|1.48μs|0.933ns|3.61ns|0.011| 0|0|808 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`ExecuteNonQuery`|net472|1.74μs|0.748ns|2.9ns|0.122| 0|0|770 B| |#5739|`ExecuteNonQuery`|net6.0|1.12μs|0.444ns|1.72ns|0.0112| 0|0|808 B| |#5739|`ExecuteNonQuery`|netcoreapp3.1|1.49μs|0.644ns|2.41ns|0.0105| 0|0|808 B| |#5739|`ExecuteNonQuery`|net472|1.76μs|4.67ns|18.1ns|0.122| 0|0|770 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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`CallElasticsearch`|net6.0|1.23μs|0.499ns|1.93ns|0.0141| 0|0|976 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`CallElasticsearch`|netcoreapp3.1|1.48μs|0.716ns|2.58ns|0.0134| 0|0|976 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`CallElasticsearch`|net472|2.43μs|1.49ns|5.77ns|0.157| 0.00121|0|995 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`CallElasticsearchAsync`|net6.0|1.23μs|1.16ns|4.34ns|0.0131| 0|0|952 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`CallElasticsearchAsync`|netcoreapp3.1|1.62μs|0.763ns|2.85ns|0.0138| 0|0|1.02 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`CallElasticsearchAsync`|net472|2.65μs|1.89ns|7.33ns|0.167| 0.00132|0|1.05 KB| |#5739|`CallElasticsearch`|net6.0|1.27μs|0.638ns|2.3ns|0.0139| 0|0|976 B| |#5739|`CallElasticsearch`|netcoreapp3.1|1.47μs|0.531ns|1.99ns|0.0133| 0|0|976 B| |#5739|`CallElasticsearch`|net472|2.55μs|1.48ns|5.73ns|0.157| 0|0|995 B| |#5739|`CallElasticsearchAsync`|net6.0|1.19μs|1.12ns|4.18ns|0.0132| 0|0|952 B| |#5739|`CallElasticsearchAsync`|netcoreapp3.1|1.65μs|0.759ns|2.94ns|0.0141| 0|0|1.02 KB| |#5739|`CallElasticsearchAsync`|net472|2.56μs|1.64ns|6.13ns|0.166| 0|0|1.05 KB|
Benchmarks.Trace.GraphQLBenchmark - 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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`ExecuteAsync`|net6.0|1.22μs|0.474ns|1.84ns|0.0135| 0|0|952 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`ExecuteAsync`|netcoreapp3.1|1.68μs|2.5ns|9.69ns|0.0126| 0|0|952 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`ExecuteAsync`|net472|1.78μs|1.12ns|4.32ns|0.145| 0|0|915 B| |#5739|`ExecuteAsync`|net6.0|1.25μs|1.53ns|5.74ns|0.0132| 0|0|952 B| |#5739|`ExecuteAsync`|netcoreapp3.1|1.65μs|4.53ns|17.6ns|0.0122| 0|0|952 B| |#5739|`ExecuteAsync`|net472|1.78μs|0.867ns|3.24ns|0.145| 0|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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendAsync`|net6.0|4.22μs|2.32ns|8.99ns|0.0295| 0|0|2.22 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendAsync`|netcoreapp3.1|5.12μs|2.73ns|10.2ns|0.0382| 0|0|2.76 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendAsync`|net472|7.52μs|1.46ns|5.45ns|0.499| 0|0|3.15 KB| |#5739|`SendAsync`|net6.0|4.12μs|1.36ns|4.9ns|0.031| 0|0|2.22 KB| |#5739|`SendAsync`|netcoreapp3.1|5.14μs|2.05ns|7.92ns|0.0359| 0|0|2.76 KB| |#5739|`SendAsync`|net472|7.59μs|2.1ns|7.85ns|0.498| 0|0|3.15 KB|
Benchmarks.Trace.ILoggerBenchmark - Faster :tada: Same allocations :heavy_check_mark: #### Faster :tada: in #5739 | Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality | |:----------|-----------:|-----------:|--------:|--------:| | Benchmarks.Trace.ILoggerBenchmark.EnrichedLog‑net6.0 | 1.136 | 1,608.03 | 1,415.70 | ### Raw results | Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated | |---------|---------------------------- |-------------- |---------:|---------:|--------:|-------:|------:|------:|----------:| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net6.0|1.61μs|0.474ns|1.71ns|0.0226| 0|0|1.64 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|netcoreapp3.1|2.1μs|0.702ns|2.63ns|0.0221| 0|0|1.64 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net472|2.62μs|1.87ns|7.01ns|0.25| 0|0|1.57 KB| |#5739|`EnrichedLog`|net6.0|1.42μs|0.426ns|1.54ns|0.0234| 0|0|1.64 KB| |#5739|`EnrichedLog`|netcoreapp3.1|2.22μs|0.608ns|2.28ns|0.0222| 0|0|1.64 KB| |#5739|`EnrichedLog`|net472|2.6μs|1.9ns|7.11ns|0.249| 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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net6.0|114μs|261ns|1.01μs|0.057| 0|0|4.28 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|netcoreapp3.1|119μs|188ns|726ns|0.0605| 0|0|4.28 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net472|147μs|97.3ns|377ns|0.658| 0.219|0|4.46 KB| |#5739|`EnrichedLog`|net6.0|113μs|40.7ns|141ns|0.0566| 0|0|4.28 KB| |#5739|`EnrichedLog`|netcoreapp3.1|117μs|173ns|670ns|0.0583| 0|0|4.28 KB| |#5739|`EnrichedLog`|net472|147μs|65.9ns|255ns|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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net6.0|2.93μs|0.882ns|3.42ns|0.0304| 0|0|2.2 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|netcoreapp3.1|4.1μs|1.35ns|4.86ns|0.0288| 0|0|2.2 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net472|4.87μs|5.57ns|19.3ns|0.32| 0|0|2.02 KB| |#5739|`EnrichedLog`|net6.0|3.17μs|0.983ns|3.81ns|0.0303| 0|0|2.2 KB| |#5739|`EnrichedLog`|netcoreapp3.1|4.09μs|1.62ns|6.26ns|0.0285| 0|0|2.2 KB| |#5739|`EnrichedLog`|net472|4.94μs|1.42ns|5.51ns|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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendReceive`|net6.0|1.32μs|0.73ns|2.73ns|0.0159| 0|0|1.14 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendReceive`|netcoreapp3.1|1.74μs|1.63ns|6.32ns|0.0149| 0|0|1.14 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`SendReceive`|net472|1.98μs|1.51ns|5.67ns|0.183| 0.000988|0|1.16 KB| |#5739|`SendReceive`|net6.0|1.31μs|1.51ns|5.83ns|0.0157| 0|0|1.14 KB| |#5739|`SendReceive`|netcoreapp3.1|1.78μs|1.42ns|5.51ns|0.015| 0|0|1.14 KB| |#5739|`SendReceive`|net472|2.09μs|0.832ns|3.11ns|0.183| 0|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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net6.0|2.76μs|0.51ns|1.91ns|0.022| 0|0|1.6 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|netcoreapp3.1|3.83μs|2.96ns|11.1ns|0.0226| 0|0|1.65 KB| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`EnrichedLog`|net472|4.34μs|1.34ns|5.02ns|0.323| 0|0|2.04 KB| |#5739|`EnrichedLog`|net6.0|2.74μs|1.03ns|4ns|0.022| 0|0|1.6 KB| |#5739|`EnrichedLog`|netcoreapp3.1|3.99μs|1.57ns|6.08ns|0.0221| 0|0|1.65 KB| |#5739|`EnrichedLog`|net472|4.33μs|1.97ns|7.64ns|0.322| 0|0|2.04 KB|
Benchmarks.Trace.SpanBenchmark - Faster :tada: Same allocations :heavy_check_mark: #### Faster :tada: in #5739 | Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality | |:----------|-----------:|-----------:|--------:|--------:| | Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 | 1.129 | 550.64 | 487.91 | ### Raw results | Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated | |---------|---------------------------- |-------------- |---------:|---------:|--------:|-------:|------:|------:|----------:| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartFinishSpan`|net6.0|403ns|0.338ns|1.31ns|0.0081| 0|0|576 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartFinishSpan`|netcoreapp3.1|602ns|0.431ns|1.55ns|0.00789| 0|0|576 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartFinishSpan`|net472|686ns|0.62ns|2.4ns|0.0915| 0|0|578 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartFinishScope`|net6.0|551ns|0.815ns|3.16ns|0.00967| 0|0|696 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartFinishScope`|netcoreapp3.1|703ns|0.375ns|1.45ns|0.00948| 0|0|696 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`StartFinishScope`|net472|869ns|0.795ns|3.08ns|0.105| 0|0|658 B| |#5739|`StartFinishSpan`|net6.0|407ns|0.191ns|0.74ns|0.00813| 0|0|576 B| |#5739|`StartFinishSpan`|netcoreapp3.1|554ns|0.491ns|1.9ns|0.00782| 0|0|576 B| |#5739|`StartFinishSpan`|net472|619ns|0.49ns|1.9ns|0.0916| 0|0|578 B| |#5739|`StartFinishScope`|net6.0|488ns|0.256ns|0.99ns|0.0098| 0|0|696 B| |#5739|`StartFinishScope`|netcoreapp3.1|725ns|0.329ns|1.27ns|0.00946| 0|0|696 B| |#5739|`StartFinishScope`|net472|862ns|1.11ns|4.31ns|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](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`RunOnMethodBegin`|net6.0|607ns|0.164ns|0.636ns|0.00971| 0|0|696 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`RunOnMethodBegin`|netcoreapp3.1|882ns|0.563ns|2.1ns|0.0093| 0|0|696 B| |[master](https://github.com/DataDog/dd-trace-dotnet/tree/0f17e5756636c7ced13cdd7d003fe6dbca1039dc)|`RunOnMethodBegin`|net472|1.04μs|0.653ns|2.53ns|0.104| 0|0|658 B| |#5739|`RunOnMethodBegin`|net6.0|667ns|0.455ns|1.64ns|0.00977| 0|0|696 B| |#5739|`RunOnMethodBegin`|netcoreapp3.1|896ns|0.446ns|1.61ns|0.00914| 0|0|696 B| |#5739|`RunOnMethodBegin`|net472|1.12μs|0.386ns|1.5ns|0.104| 0|0|658 B|
bouwkast commented 6 days ago

LGTM, was only wondering how often this could happen that would make it worth adding some logging if so.

From the initial discovery/fix of this in #5690 we only saw a few instance of the actual exception in error tracking, so it may be relatively rare.

I don't think that logging would be that beneficial here as I think we understand the cause of it now and have some future action items to look into with how we could improve this bit of code and how exactly this would work with non-W3C IDs.