dd-trace-dotnet icon indicating copy to clipboard operation
dd-trace-dotnet copied to clipboard

add test for DSM context reuse in async context

Open vandonr opened this issue 1 year ago • 3 comments

This PR is currently just demonstrating a failing test.

It's testing roughly the same thing as the test just above (that consuming and then producing keeps the chain unbroken in DSM), but with async methods.

The context is currently saved in an AsyncLocal variable https://github.com/DataDog/dd-trace-dotnet/blob/b5a855bffe6c0b2ae5d150fb6ad674363464c816/tracer/src/Datadog.Trace/DataStreamsMonitoring/DataStreamsManager.cs#L27 but my understanding is that this only has the scope of the await consume(), and it's lost once we open a new async context for the produce.

The alternatives I see are:

  • using a ThreadLocal variable instead
  • using a regular variable instead (not static ?)
  • ???

and I'm not sure what's the right choice here.

vandonr avatar Apr 04 '24 09:04 vandonr

Datadog Report

Branch report: vandonr/wip Commit report: 51a3e10 Test service: dd-trace-dotnet

:x: 24 Failed (0 Known Flaky), 264968 Passed, 1534 Skipped, 43m 21.59s Wall Time

:x: Failed Tests (24)

This report shows up to 5 failed tests.

  • WhenEnabled_AsyncConsumeThenProduceKeepsPathway - Datadog.Trace.Tests.DataStreamsMonitoring.DataStreamsManagerTests - Details

    Expand for error
    xpected points[1].ParentHash to be Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 15085792726233566605UL
    , but found Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 0UL
    .
    
    ith configuration:
     Use declared types and members
    ..
    
  • WhenEnabled_AsyncConsumeThenProduceKeepsPathway - Datadog.Trace.Tests.DataStreamsMonitoring.DataStreamsManagerTests - Details

    Expand for error
    xpected points[1].ParentHash to be Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 15085792726233566605UL
    , but found Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 0UL
    .
    
    ith configuration:
     Use declared types and members
    ..
    
  • WhenEnabled_AsyncConsumeThenProduceKeepsPathway - Datadog.Trace.Tests.DataStreamsMonitoring.DataStreamsManagerTests - Details

    Expand for error
    xpected points[1].ParentHash to be Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 15085792726233566605UL
    , but found Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 0UL
    .
    
    ith configuration:
     Use declared types and members
    ..
    
  • WhenEnabled_AsyncConsumeThenProduceKeepsPathway - Datadog.Trace.Tests.DataStreamsMonitoring.DataStreamsManagerTests - Details

    Expand for error
    xpected points[1].ParentHash to be Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 15085792726233566605UL
    , but found Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 0UL
    .
    
    ith configuration:
     Use declared types and members
    ..
    
  • WhenEnabled_AsyncConsumeThenProduceKeepsPathway - Datadog.Trace.Tests.DataStreamsMonitoring.DataStreamsManagerTests - Details

    Expand for error
    xpected points[1].ParentHash to be Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 15085792726233566605UL
    , but found Datadog.Trace.DataStreamsMonitoring.Hashes.PathwayHash
    
       Value = 0UL
    .
    
    ith configuration:
     Use declared types and members
    ..
    

datadog-ddstaging[bot] avatar Apr 04 '24 10:04 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 (5394) - mean (74ms)  : 65, 83
     .   : milestone, 74,
    master - mean (75ms)  : 65, 84
     .   : milestone, 75,

    section CallTarget+Inlining+NGEN
    This PR (5394) - mean (999ms)  : 979, 1018
     .   : milestone, 999,
    master - mean (990ms)  : 970, 1011
     .   : milestone, 990,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5394) - mean (110ms)  : 106, 113
     .   : milestone, 110,
    master - mean (110ms)  : 106, 115
     .   : milestone, 110,

    section CallTarget+Inlining+NGEN
    This PR (5394) - mean (717ms)  : 694, 739
     .   : milestone, 717,
    master - mean (712ms)  : 687, 738
     .   : milestone, 712,

gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5394) - mean (94ms)  : 91, 97
     .   : milestone, 94,
    master - mean (93ms)  : 91, 96
     .   : milestone, 93,

    section CallTarget+Inlining+NGEN
    This PR (5394) - mean (665ms)  : 643, 687
     .   : milestone, 665,
    master - mean (669ms)  : 650, 688
     .   : milestone, 669,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5394) - mean (188ms)  : 183, 192
     .   : milestone, 188,
    master - mean (188ms)  : 185, 191
     .   : milestone, 188,

    section CallTarget+Inlining+NGEN
    This PR (5394) - mean (1,074ms)  : 1052, 1096
     .   : milestone, 1074,
    master - mean (1,073ms)  : 1043, 1102
     .   : milestone, 1073,

gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5394) - mean (271ms)  : 266, 276
     .   : milestone, 271,
    master - mean (270ms)  : 265, 275
     .   : milestone, 270,

    section CallTarget+Inlining+NGEN
    This PR (5394) - mean (869ms)  : 845, 894
     .   : milestone, 869,
    master - mean (872ms)  : 838, 906
     .   : milestone, 872,

gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5394) - mean (259ms)  : 254, 265
     .   : milestone, 259,
    master - mean (260ms)  : 254, 265
     .   : milestone, 260,

    section CallTarget+Inlining+NGEN
    This PR (5394) - mean (856ms)  : 830, 883
     .   : milestone, 856,
    master - mean (853ms)  : 829, 877
     .   : milestone, 853,

andrewlock avatar Apr 04 '24 10:04 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #5394 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.197
  • All benchmarks have the same 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 8.59μs 48.1ns 330ns 0.0173 0.00863 0 7.51 KB
master StartStopWithChild netcoreapp3.1 10.7μs 55.6ns 278ns 0.0324 0.0162 0 7.6 KB
master StartStopWithChild net472 17μs 80.2ns 310ns 1.36 0.34 0.119 8.04 KB
#5394 StartStopWithChild net6.0 9.11μs 43.4ns 179ns 0.0175 0.00439 0 7.51 KB
#5394 StartStopWithChild netcoreapp3.1 10.9μs 50.3ns 207ns 0.0321 0.0161 0 7.6 KB
#5394 StartStopWithChild net472 16.8μs 62.7ns 235ns 1.35 0.351 0.114 8.05 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 453μs 218ns 845ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 589μs 119ns 444ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 815μs 142ns 530ns 0.406 0 0 3.3 KB
#5394 WriteAndFlushEnrichedTraces net6.0 455μs 131ns 490ns 0 0 0 2.7 KB
#5394 WriteAndFlushEnrichedTraces netcoreapp3.1 595μs 152ns 568ns 0 0 0 2.7 KB
#5394 WriteAndFlushEnrichedTraces net472 816μs 374ns 1.4μs 0.406 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 169μs 150ns 560ns 0.17 0 0 18.33 KB
master SendRequest netcoreapp3.1 189μs 342ns 1.33μs 0.188 0 0 20.49 KB
master SendRequest net472 0.000145ns 7.84E‑05ns 0.000293ns 0 0 0 0 b
#5394 SendRequest net6.0 172μs 175ns 679ns 0.257 0 0 18.33 KB
#5394 SendRequest netcoreapp3.1 191μs 174ns 673ns 0.191 0 0 20.49 KB
#5394 SendRequest net472 0.000846ns 0.000223ns 0.000865ns 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 WriteAndFlushEnrichedTraces net6.0 554μs 855ns 3.31μs 0.539 0 0 41.72 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 632μs 563ns 1.95μs 0.327 0 0 41.69 KB
master WriteAndFlushEnrichedTraces net472 904μs 3.54μs 13.7μs 8.42 2.66 0.443 53.35 KB
#5394 WriteAndFlushEnrichedTraces net6.0 561μs 689ns 2.67μs 0.543 0 0 41.75 KB
#5394 WriteAndFlushEnrichedTraces netcoreapp3.1 663μs 1.07μs 4.12μs 0.324 0 0 41.84 KB
#5394 WriteAndFlushEnrichedTraces net472 851μs 2.91μs 10.5μs 8.28 2.48 0.414 53.25 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.17μs 0.218ns 0.816ns 0.0112 0 0 784 B
master ExecuteNonQuery netcoreapp3.1 1.47μs 0.604ns 2.34ns 0.0105 0 0 784 B
master ExecuteNonQuery net472 1.92μs 1.28ns 4.95ns 0.118 0 0 746 B
#5394 ExecuteNonQuery net6.0 1.16μs 0.39ns 1.46ns 0.0112 0 0 784 B
#5394 ExecuteNonQuery netcoreapp3.1 1.46μs 0.705ns 2.44ns 0.0109 0 0 784 B
#5394 ExecuteNonQuery net472 1.75μs 2.1ns 8.13ns 0.118 0 0 746 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.35μs 0.358ns 1.34ns 0.0142 0 0 1.01 KB
master CallElasticsearch netcoreapp3.1 1.61μs 1.16ns 4.19ns 0.0137 0 0 1.01 KB
master CallElasticsearch net472 2.57μs 1.48ns 5.74ns 0.162 0 0 1.02 KB
master CallElasticsearchAsync net6.0 1.38μs 0.851ns 3.3ns 0.0138 0 0 984 B
master CallElasticsearchAsync netcoreapp3.1 1.74μs 0.655ns 2.54ns 0.014 0 0 1.06 KB
master CallElasticsearchAsync net472 2.69μs 2.79ns 10.8ns 0.171 0.00134 0 1.08 KB
#5394 CallElasticsearch net6.0 1.34μs 0.641ns 2.48ns 0.0139 0 0 1.01 KB
#5394 CallElasticsearch netcoreapp3.1 1.62μs 1.69ns 6.08ns 0.0136 0 0 1.01 KB
#5394 CallElasticsearch net472 2.65μs 1.86ns 6.95ns 0.161 0 0 1.02 KB
#5394 CallElasticsearchAsync net6.0 1.44μs 1.07ns 4.01ns 0.0137 0 0 984 B
#5394 CallElasticsearchAsync netcoreapp3.1 1.77μs 1.93ns 7.48ns 0.0141 0 0 1.06 KB
#5394 CallElasticsearchAsync net472 2.61μs 1.99ns 7.71ns 0.17 0 0 1.08 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 ExecuteAsync net6.0 1.41μs 0.881ns 3.41ns 0.0127 0 0 928 B
master ExecuteAsync netcoreapp3.1 1.69μs 1.47ns 5.68ns 0.012 0 0 928 B
master ExecuteAsync net472 1.9μs 1.5ns 5.41ns 0.141 0.000949 0 891 B
#5394 ExecuteAsync net6.0 1.3μs 0.799ns 2.99ns 0.013 0 0 928 B
#5394 ExecuteAsync netcoreapp3.1 1.72μs 0.588ns 2.12ns 0.0128 0 0 928 B
#5394 ExecuteAsync net472 1.98μs 1.34ns 5.17ns 0.141 0.000974 0 891 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.13μs 3.15ns 11.8ns 0.0288 0 0 2.16 KB
master SendAsync netcoreapp3.1 5.06μs 2.89ns 10.4ns 0.0353 0 0 2.7 KB
master SendAsync net472 7.63μs 2.32ns 8.36ns 0.484 0 0 3.05 KB
#5394 SendAsync net6.0 4.23μs 4.03ns 15.1ns 0.0296 0 0 2.16 KB
#5394 SendAsync netcoreapp3.1 5.19μs 2.21ns 8.56ns 0.0363 0 0 2.7 KB
#5394 SendAsync net472 7.62μs 3.51ns 13.6ns 0.484 0 0 3.05 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.47μs 2.71ns 9.76ns 0.0228 0 0 1.65 KB
master EnrichedLog netcoreapp3.1 2.17μs 0.625ns 2.34ns 0.0228 0 0 1.65 KB
master EnrichedLog net472 2.67μs 1.62ns 6.27ns 0.25 0 0 1.57 KB
#5394 EnrichedLog net6.0 1.59μs 0.491ns 1.84ns 0.023 0 0 1.65 KB
#5394 EnrichedLog netcoreapp3.1 2.27μs 0.928ns 3.59ns 0.0225 0 0 1.65 KB
#5394 EnrichedLog net472 2.74μs 2.65ns 10.3ns 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 110μs 74.3ns 288ns 0.0553 0 0 4.23 KB
master EnrichedLog netcoreapp3.1 116μs 109ns 420ns 0 0 0 4.23 KB
master EnrichedLog net472 146μs 62ns 240ns 0.657 0.219 0 4.41 KB
#5394 EnrichedLog net6.0 112μs 97.9ns 379ns 0 0 0 4.23 KB
#5394 EnrichedLog netcoreapp3.1 118μs 191ns 740ns 0 0 0 4.23 KB
#5394 EnrichedLog net472 147μs 139ns 518ns 0.657 0.219 0 4.41 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 3μs 1.44ns 5.18ns 0.0315 0 0 2.21 KB
master EnrichedLog netcoreapp3.1 4.3μs 2.26ns 8.73ns 0.0301 0 0 2.21 KB
master EnrichedLog net472 4.9μs 1.46ns 5.67ns 0.32 0 0 2.02 KB
#5394 EnrichedLog net6.0 3.2μs 1.14ns 4.43ns 0.0318 0 0 2.21 KB
#5394 EnrichedLog netcoreapp3.1 4.21μs 2.83ns 10.6ns 0.0294 0 0 2.21 KB
#5394 EnrichedLog net472 5.04μs 6.8ns 26.3ns 0.32 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.49μs 1.03ns 3.71ns 0.0163 0 0 1.18 KB
master SendReceive netcoreapp3.1 1.83μs 1.19ns 4.61ns 0.0155 0 0 1.18 KB
master SendReceive net472 2.12μs 0.93ns 3.48ns 0.187 0 0 1.18 KB
#5394 SendReceive net6.0 1.38μs 0.465ns 1.61ns 0.0166 0 0 1.18 KB
#5394 SendReceive netcoreapp3.1 1.89μs 0.981ns 3.54ns 0.0161 0 0 1.18 KB
#5394 SendReceive net472 2.28μs 1.37ns 5.31ns 0.187 0.00114 0 1.18 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.77μs 0.695ns 2.6ns 0.0207 0 0 1.55 KB
master EnrichedLog netcoreapp3.1 4.01μs 2.92ns 10.9ns 0.0201 0 0 1.6 KB
master EnrichedLog net472 4.45μs 2.84ns 11ns 0.316 0 0 1.99 KB
#5394 EnrichedLog net6.0 2.71μs 0.629ns 2.35ns 0.0217 0 0 1.55 KB
#5394 EnrichedLog netcoreapp3.1 4.04μs 1.35ns 5.24ns 0.0202 0 0 1.6 KB
#5394 EnrichedLog net472 4.5μs 10.4ns 40.3ns 0.316 0 0 1.99 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 524ns 0.278ns 1.04ns 0.00775 0 0 552 B
master StartFinishSpan netcoreapp3.1 692ns 1.59ns 6.15ns 0.00736 0 0 552 B
master StartFinishSpan net472 740ns 1.2ns 4.65ns 0.0877 0 0 554 B
master StartFinishScope net6.0 575ns 1.29ns 4.84ns 0.00954 0 0 672 B
master StartFinishScope netcoreapp3.1 824ns 1.4ns 5.43ns 0.00893 0 0 672 B
master StartFinishScope net472 929ns 1.94ns 7.51ns 0.101 0 0 634 B
#5394 StartFinishSpan net6.0 513ns 1.05ns 4.07ns 0.00763 0 0 552 B
#5394 StartFinishSpan netcoreapp3.1 697ns 1.22ns 4.72ns 0.00734 0 0 552 B
#5394 StartFinishSpan net472 793ns 1.39ns 5.37ns 0.0877 0 0 554 B
#5394 StartFinishScope net6.0 591ns 0.687ns 2.57ns 0.00938 0 0 672 B
#5394 StartFinishScope netcoreapp3.1 822ns 1.24ns 4.63ns 0.00899 0 0 672 B
#5394 StartFinishScope net472 924ns 1.14ns 4.41ns 0.1 0 0 634 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #5394

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑netcoreapp3.1 1.197 1,072.73 896.54

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 691ns 1.01ns 3.92ns 0.00933 0 0 672 B
master RunOnMethodBegin netcoreapp3.1 1.07μs 2.59ns 10ns 0.00904 0 0 672 B
master RunOnMethodBegin net472 1.13μs 2.24ns 8.68ns 0.1 0 0 634 B
#5394 RunOnMethodBegin net6.0 633ns 0.896ns 3.47ns 0.00955 0 0 672 B
#5394 RunOnMethodBegin netcoreapp3.1 896ns 1.95ns 7.55ns 0.00908 0 0 672 B
#5394 RunOnMethodBegin net472 1.07μs 1.9ns 7.34ns 0.101 0 0 634 B

andrewlock avatar Apr 04 '24 11:04 andrewlock