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

[Profiler] Improve EtwEventsManager cleanup

Open chrisnas opened this issue 1 year ago • 4 comments

Summary of changes

Avoid closing already closed named pipe server

Reason for change

One test was failing in x86

Implementation details

Test coverage

Other details

chrisnas avatar Oct 23 '24 17:10 chrisnas

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 (6189) - mean (71ms)  : 68, 73
     .   : milestone, 71,
    master - mean (71ms)  : 68, 75
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (6189) - mean (1,115ms)  : 1086, 1144
     .   : milestone, 1115,
    master - mean (1,118ms)  : 1096, 1140
     .   : milestone, 1118,


gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6189) - mean (111ms)  : 108, 114
     .   : milestone, 111,
    master - mean (110ms)  : 107, 114
     .   : milestone, 110,

    section CallTarget+Inlining+NGEN
    This PR (6189) - mean (777ms)  : 763, 790
     .   : milestone, 777,
    master - mean (778ms)  : 762, 793
     .   : milestone, 778,


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

    section CallTarget+Inlining+NGEN
    This PR (6189) - mean (734ms)  : 718, 751
     .   : milestone, 734,
    master - mean (733ms)  : 718, 749
     .   : milestone, 733,


gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6189) - mean (190ms)  : 186, 194
     .   : milestone, 190,
    master - mean (190ms)  : 188, 193
     .   : milestone, 190,

    section CallTarget+Inlining+NGEN
    This PR (6189) - mean (1,201ms)  : 1176, 1226
     .   : milestone, 1201,
    master - mean (1,201ms)  : 1175, 1228
     .   : milestone, 1201,


gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6189) - mean (276ms)  : 272, 281
     .   : milestone, 276,
    master - mean (276ms)  : 271, 280
     .   : milestone, 276,

    section CallTarget+Inlining+NGEN
    This PR (6189) - mean (947ms)  : 927, 968
     .   : milestone, 947,
    master - mean (949ms)  : 927, 971
     .   : milestone, 949,


gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6189) - mean (264ms)  : 258, 271
     .   : milestone, 264,
    master - mean (265ms)  : 261, 268
     .   : milestone, 265,

    section CallTarget+Inlining+NGEN
    This PR (6189) - mean (935ms)  : 918, 952
     .   : milestone, 935,
    master - mean (924ms)  : 905, 943
     .   : milestone, 924,

andrewlock avatar Oct 23 '24 18:10 andrewlock

Datadog Report

Branch report: chrisnas/etw_no_agent_case Commit report: 322e4f6 Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 365605 Passed, 2410 Skipped, 17h 14m 13.75s Total Time

datadog-ddstaging[bot] avatar Oct 23 '24 18:10 datadog-ddstaging[bot]

Benchmarks Report for tracer :snail:

Benchmarks for #6189 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.173
  • 1 benchmarks are slower, with geometric mean 1.247
  • 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 7.66μs 38.2ns 175ns 0.0119 0.00396 0 5.42 KB
master StartStopWithChild netcoreapp3.1 9.84μs 53.7ns 294ns 0.0147 0.00489 0 5.62 KB
master StartStopWithChild net472 16.3μs 49.8ns 186ns 1.03 0.318 0.0896 6.06 KB
#6189 StartStopWithChild net6.0 7.83μs 43.2ns 266ns 0.0118 0.00393 0 5.43 KB
#6189 StartStopWithChild netcoreapp3.1 10μs 56.1ns 392ns 0.0198 0.00992 0 5.62 KB
#6189 StartStopWithChild net472 16.4μs 62.5ns 242ns 1.02 0.309 0.0894 6.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 471μs 231ns 865ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 621μs 295ns 1.14μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 893μs 330ns 1.19μs 0.437 0 0 3.3 KB
#6189 WriteAndFlushEnrichedTraces net6.0 482μs 332ns 1.2μs 0 0 0 2.7 KB
#6189 WriteAndFlushEnrichedTraces netcoreapp3.1 639μs 188ns 729ns 0 0 0 2.7 KB
#6189 WriteAndFlushEnrichedTraces net472 846μs 429ns 1.6μs 0.419 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 196μs 1.1μs 8.59μs 0.212 0 0 18.45 KB
master SendRequest netcoreapp3.1 225μs 1.32μs 12.4μs 0.218 0 0 20.61 KB
master SendRequest net472 9.94E‑06ns 9.94E‑06ns 3.85E‑05ns 0 0 0 0 b
#6189 SendRequest net6.0 202μs 1.14μs 10.9μs 0.21 0 0 18.45 KB
#6189 SendRequest netcoreapp3.1 222μs 1.27μs 9.64μs 0.217 0 0 20.61 KB
#6189 SendRequest net472 7.95E‑07ns 7.95E‑07ns 2.75E‑06ns 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 572μs 2.04μs 7.37μs 0.584 0 0 41.52 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 678μs 3.36μs 13.9μs 0.327 0 0 41.83 KB
master WriteAndFlushEnrichedTraces net472 885μs 3.04μs 11.4μs 8.74 2.62 0.437 53.37 KB
#6189 WriteAndFlushEnrichedTraces net6.0 593μs 3.21μs 18.4μs 0.573 0 0 41.71 KB
#6189 WriteAndFlushEnrichedTraces netcoreapp3.1 690μs 3.69μs 19.2μs 0.336 0 0 41.66 KB
#6189 WriteAndFlushEnrichedTraces net472 917μs 4.86μs 23.8μs 8.04 2.23 0.446 53.31 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.41μs 1.37ns 5.29ns 0.0142 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.76μs 1.52ns 5.9ns 0.0141 0 0 1.02 KB
master ExecuteNonQuery net472 2.06μs 2.19ns 8.48ns 0.156 0 0 987 B
#6189 ExecuteNonQuery net6.0 1.32μs 0.932ns 3.61ns 0.0145 0 0 1.02 KB
#6189 ExecuteNonQuery netcoreapp3.1 1.73μs 0.867ns 3ns 0.0138 0 0 1.02 KB
#6189 ExecuteNonQuery net472 2.11μs 1.78ns 6.67ns 0.156 0 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6189

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearch‑net6.0 1.128 1,251.65 1,110.10

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.25μs 0.447ns 1.67ns 0.0138 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.5μs 0.832ns 2.88ns 0.0132 0 0 976 B
master CallElasticsearch net472 2.51μs 1.42ns 5.3ns 0.158 0 0 995 B
master CallElasticsearchAsync net6.0 1.36μs 0.515ns 1.93ns 0.0131 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.58μs 0.55ns 2.06ns 0.0135 0 0 1.02 KB
master CallElasticsearchAsync net472 2.54μs 1.6ns 5.99ns 0.166 0 0 1.05 KB
#6189 CallElasticsearch net6.0 1.11μs 0.869ns 3.25ns 0.014 0 0 976 B
#6189 CallElasticsearch netcoreapp3.1 1.47μs 0.679ns 2.54ns 0.0133 0 0 976 B
#6189 CallElasticsearch net472 2.46μs 2ns 7.49ns 0.157 0 0 995 B
#6189 CallElasticsearchAsync net6.0 1.3μs 0.52ns 1.94ns 0.013 0 0 952 B
#6189 CallElasticsearchAsync netcoreapp3.1 1.62μs 0.951ns 3.68ns 0.0138 0 0 1.02 KB
#6189 CallElasticsearchAsync net472 2.63μs 2.55ns 9.88ns 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 ExecuteAsync net6.0 1.2μs 0.484ns 1.68ns 0.0132 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.61μs 0.434ns 1.62ns 0.0129 0 0 952 B
master ExecuteAsync net472 1.8μs 0.733ns 2.64ns 0.145 0 0 915 B
#6189 ExecuteAsync net6.0 1.16μs 0.768ns 2.87ns 0.0134 0 0 952 B
#6189 ExecuteAsync netcoreapp3.1 1.62μs 1.03ns 3.86ns 0.0122 0 0 952 B
#6189 ExecuteAsync net472 1.77μs 0.383ns 1.43ns 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 SendAsync net6.0 4.15μs 2.37ns 8.88ns 0.031 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.09μs 2.33ns 8.71ns 0.0381 0 0 2.76 KB
master SendAsync net472 7.76μs 1.9ns 7.35ns 0.498 0 0 3.15 KB
#6189 SendAsync net6.0 4.16μs 1.68ns 6.51ns 0.0312 0 0 2.22 KB
#6189 SendAsync netcoreapp3.1 5.17μs 1.48ns 5.32ns 0.0361 0 0 2.76 KB
#6189 SendAsync net472 7.89μs 1.46ns 5.67ns 0.499 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.55μs 0.725ns 2.62ns 0.0231 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.08μs 0.824ns 3.08ns 0.022 0 0 1.64 KB
master EnrichedLog net472 2.49μs 1.36ns 5.07ns 0.249 0 0 1.57 KB
#6189 EnrichedLog net6.0 1.47μs 3.04ns 11.8ns 0.0226 0 0 1.64 KB
#6189 EnrichedLog netcoreapp3.1 2.11μs 1.3ns 4.68ns 0.0222 0 0 1.64 KB
#6189 EnrichedLog net472 2.57μs 1.01ns 3.93ns 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 EnrichedLog net6.0 116μs 153ns 573ns 0.0583 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 122μs 86.3ns 311ns 0.0606 0 0 4.28 KB
master EnrichedLog net472 153μs 148ns 572ns 0.69 0.23 0 4.46 KB
#6189 EnrichedLog net6.0 119μs 174ns 651ns 0 0 0 4.28 KB
#6189 EnrichedLog netcoreapp3.1 123μs 259ns 1μs 0 0 0 4.28 KB
#6189 EnrichedLog net472 153μs 117ns 437ns 0.685 0.228 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 3.06μs 0.767ns 2.87ns 0.0307 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.22μs 1.49ns 5.77ns 0.0294 0 0 2.2 KB
master EnrichedLog net472 4.89μs 2.67ns 10.4ns 0.32 0 0 2.02 KB
#6189 EnrichedLog net6.0 3.08μs 1.3ns 5.04ns 0.0308 0 0 2.2 KB
#6189 EnrichedLog netcoreapp3.1 4.23μs 1.61ns 6.22ns 0.0294 0 0 2.2 KB
#6189 EnrichedLog net472 4.88μs 3ns 11.2ns 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.39μs 0.816ns 3.16ns 0.016 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.79μs 0.844ns 2.92ns 0.0156 0 0 1.14 KB
master SendReceive net472 2.18μs 1.04ns 4.05ns 0.183 0.00109 0 1.16 KB
#6189 SendReceive net6.0 1.3μs 1.1ns 4.25ns 0.0163 0 0 1.14 KB
#6189 SendReceive netcoreapp3.1 1.72μs 1.25ns 4.85ns 0.0154 0 0 1.14 KB
#6189 SendReceive net472 2.01μs 0.806ns 3.02ns 0.183 0.00101 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.76μs 0.913ns 3.42ns 0.022 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.89μs 2.25ns 8.44ns 0.0215 0 0 1.65 KB
master EnrichedLog net472 4.46μs 4.67ns 18.1ns 0.322 0 0 2.04 KB
#6189 EnrichedLog net6.0 2.7μs 0.799ns 2.99ns 0.0214 0 0 1.6 KB
#6189 EnrichedLog netcoreapp3.1 3.88μs 2.1ns 7.85ns 0.0214 0 0 1.65 KB
#6189 EnrichedLog net472 4.43μs 4.45ns 17.2ns 0.323 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6189

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 1.247 492.91 614.45

Faster :tada: in #6189

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.221 490.44 401.74

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 490ns 0.31ns 1.2ns 0.00809 0 0 576 B
master StartFinishSpan netcoreapp3.1 603ns 0.916ns 3.3ns 0.00775 0 0 576 B
master StartFinishSpan net472 683ns 0.282ns 1.09ns 0.0916 0 0 578 B
master StartFinishScope net6.0 493ns 0.255ns 0.987ns 0.00968 0 0 696 B
master StartFinishScope netcoreapp3.1 754ns 4.12ns 22.5ns 0.0093 0 0 696 B
master StartFinishScope net472 902ns 0.969ns 3.75ns 0.104 0 0 658 B
#6189 StartFinishSpan net6.0 402ns 0.145ns 0.56ns 0.00808 0 0 576 B
#6189 StartFinishSpan netcoreapp3.1 562ns 0.212ns 0.82ns 0.00784 0 0 576 B
#6189 StartFinishSpan net472 701ns 0.256ns 0.99ns 0.0915 0 0 578 B
#6189 StartFinishScope net6.0 615ns 0.159ns 0.595ns 0.00984 0 0 696 B
#6189 StartFinishScope netcoreapp3.1 771ns 0.557ns 2.16ns 0.00923 0 0 696 B
#6189 StartFinishScope net472 901ns 0.705ns 2.64ns 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 647ns 0.516ns 2ns 0.00971 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 960ns 0.623ns 2.41ns 0.00958 0 0 696 B
master RunOnMethodBegin net472 1.09μs 0.976ns 3.78ns 0.104 0 0 658 B
#6189 RunOnMethodBegin net6.0 612ns 0.315ns 1.22ns 0.0098 0 0 696 B
#6189 RunOnMethodBegin netcoreapp3.1 883ns 0.448ns 1.73ns 0.00927 0 0 696 B
#6189 RunOnMethodBegin net472 1.07μs 0.388ns 1.45ns 0.104 0 0 658 B

andrewlock avatar Oct 23 '24 19:10 andrewlock

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 (6189) (11.119M)   : 0, 11119369
    master (11.292M)   : 0, 11291882
    benchmarks/2.9.0 (11.081M)   : 0, 11080577

    section Automatic
    This PR (6189) (7.417M)   : 0, 7417071
    master (7.471M)   : 0, 7470618
    benchmarks/2.9.0 (7.732M)   : 0, 7732233

    section Trace stats
    master (7.854M)   : 0, 7853541

    section Manual
    master (11.178M)   : 0, 11177916

    section Manual + Automatic
    This PR (6189) (6.915M)   : 0, 6915329
    master (6.983M)   : 0, 6983283

    section DD_TRACE_ENABLED=0
    master (10.353M)   : 0, 10352817


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6189) (9.470M)   : 0, 9470162
    master (9.759M)   : 0, 9758573
    benchmarks/2.9.0 (9.798M)   : 0, 9798067

    section Automatic
    This PR (6189) (6.585M)   : 0, 6584972
    master (6.447M)   : 0, 6446582

    section Trace stats
    master (6.536M)   : 0, 6536083

    section Manual
    master (9.551M)   : 0, 9551044

    section Manual + Automatic
    This PR (6189) (6.102M)   : 0, 6101835
    master (6.282M)   : 0, 6282382

    section DD_TRACE_ENABLED=0
    master (8.955M)   : 0, 8955266


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6189) (9.832M)   : 0, 9831829
    master (9.819M)   : 0, 9818915
    benchmarks/2.9.0 (10.067M)   : 0, 10067315

    section Automatic
    This PR (6189) (6.290M)   : 0, 6290305
    master (6.429M)   : 0, 6429392
    benchmarks/2.9.0 (7.552M)   : 0, 7552193

    section Trace stats
    master (7.215M)   : 0, 7214864

    section Manual
    master (9.879M)   : 0, 9879197

    section Manual + Automatic
    This PR (6189) (6.234M)   : 0, 6233538
    master (5.890M)   : 0, 5889975

    section DD_TRACE_ENABLED=0
    master (9.240M)   : 0, 9240298

andrewlock avatar Oct 23 '24 19:10 andrewlock