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

[WIP] Add metrics in profiler

Open gleocadie opened this issue 1 year ago • 3 comments

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

gleocadie avatar Oct 23 '24 09:10 gleocadie

Datadog Report

Branch report: gleocadie/add-metrics-for-profiler Commit report: fb128e2 Test service: dd-trace-dotnet

:x: 2 Failed (1 Known Flaky), 154366 Passed, 752 Skipped, 6h 26m 13.78s Total Time

:x: Failed Tests (2)

  • ShouldGetAllocationSamplesViaEtw - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error
    
    ctual:   Falseilure
    
  • ShouldGetLockContentionSamplesViaEtw - Datadog.Profiler.IntegrationTests.Contention.ContentionProfilerTest - :snowflake: Known flaky - Details

    Expand for error
    
    ctual:   Falseilure
    

datadog-ddstaging[bot] avatar Oct 23 '24 09:10 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 (6183) - mean (74ms)  : 69, 79
     .   : milestone, 74,
    master - mean (71ms)  : 68, 75
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (6183) - mean (1,150ms)  : 1121, 1179
     .   : milestone, 1150,
    master - mean (1,120ms)  : 1092, 1149
     .   : milestone, 1120,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6183) - mean (117ms)  : 108, 125
     .   : milestone, 117,
    master - mean (109ms)  : 107, 112
     .   : milestone, 109,

    section CallTarget+Inlining+NGEN
    This PR (6183) - mean (774ms)  : 757, 791
     .   : milestone, 774,
    master - mean (776ms)  : 757, 795
     .   : milestone, 776,

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

    section CallTarget+Inlining+NGEN
    This PR (6183) - mean (724ms)  : 705, 743
     .   : milestone, 724,
    master - mean (728ms)  : 710, 746
     .   : milestone, 728,

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

    section CallTarget+Inlining+NGEN
    This PR (6183) - mean (1,201ms)  : 1182, 1219
     .   : milestone, 1201,
    master - mean (1,193ms)  : 1168, 1218
     .   : milestone, 1193,

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

    section CallTarget+Inlining+NGEN
    This PR (6183) - mean (939ms)  : 923, 955
     .   : milestone, 939,
    master - mean (943ms)  : 924, 961
     .   : milestone, 943,

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

    section CallTarget+Inlining+NGEN
    This PR (6183) - mean (924ms)  : 906, 942
     .   : milestone, 924,
    master - mean (923ms)  : 907, 938
     .   : milestone, 923,

andrewlock avatar Oct 23 '24 09:10 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #6183 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.137
  • 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.59μs 43ns 292ns 0.0268 0.0153 0.00383 5.42 KB
master StartStopWithChild netcoreapp3.1 9.82μs 51.6ns 253ns 0.0204 0.0102 0 5.62 KB
master StartStopWithChild net472 16.4μs 55.4ns 215ns 1.01 0.304 0.0904 6.06 KB
#6183 StartStopWithChild net6.0 7.55μs 42.3ns 296ns 0.0113 0.00752 0 5.43 KB
#6183 StartStopWithChild netcoreapp3.1 9.92μs 53.5ns 312ns 0.0148 0.00494 0 5.61 KB
#6183 StartStopWithChild net472 16.8μs 70.7ns 274ns 0.999 0.284 0.0812 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 482μs 225ns 841ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 632μs 284ns 1.1μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 841μs 324ns 1.21μs 0.417 0 0 3.3 KB
#6183 WriteAndFlushEnrichedTraces net6.0 475μs 269ns 1.04μs 0 0 0 2.7 KB
#6183 WriteAndFlushEnrichedTraces netcoreapp3.1 646μs 527ns 2.04μs 0 0 0 2.7 KB
#6183 WriteAndFlushEnrichedTraces net472 837μs 366ns 1.42μ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 202μs 1.15μs 11.3μs 0.196 0 0 18.45 KB
master SendRequest netcoreapp3.1 222μs 1.27μs 10.5μs 0.209 0 0 20.61 KB
master SendRequest net472 0.000402ns 0.000281ns 0.00105ns 0 0 0 0 b
#6183 SendRequest net6.0 205μs 1.19μs 10.5μs 0.203 0 0 18.45 KB
#6183 SendRequest netcoreapp3.1 228μs 1.34μs 12.6μs 0.217 0 0 20.61 KB
#6183 SendRequest net472 0.00107ns 0.000525ns 0.00189ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed :heavy_check_mark: Fewer allocations :tada:

Fewer allocations :tada: in #6183

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1 41.93 KB 41.7 KB -235 B -0.56%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 578μs 3.02μs 14.8μs 0.558 0 0 41.56 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 696μs 3.34μs 14.2μs 0.355 0 0 41.93 KB
master WriteAndFlushEnrichedTraces net472 868μs 4.34μs 18.4μs 8.19 2.59 0.431 53.27 KB
#6183 WriteAndFlushEnrichedTraces net6.0 561μs 2.93μs 15.2μs 0.595 0 0 41.62 KB
#6183 WriteAndFlushEnrichedTraces netcoreapp3.1 679μs 2.57μs 9.62μs 0.353 0 0 41.7 KB
#6183 WriteAndFlushEnrichedTraces net472 882μs 4.29μs 17.2μs 8.13 2.57 0.428 53.28 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.3μs 1.16ns 4.5ns 0.0143 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.79μs 1.74ns 6.73ns 0.0135 0 0 1.02 KB
master ExecuteNonQuery net472 2.1μs 1.65ns 5.94ns 0.156 0 0 987 B
#6183 ExecuteNonQuery net6.0 1.24μs 0.954ns 3.69ns 0.0142 0 0 1.02 KB
#6183 ExecuteNonQuery netcoreapp3.1 1.75μs 1.73ns 6.72ns 0.0141 0 0 1.02 KB
#6183 ExecuteNonQuery net472 2.1μs 2.16ns 8.36ns 0.157 0.00105 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.23μs 0.726ns 2.72ns 0.0138 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.46μs 0.507ns 1.9ns 0.0132 0 0 976 B
master CallElasticsearch net472 2.53μs 1.84ns 7.14ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.27μs 0.763ns 2.96ns 0.0133 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.56μs 2.71ns 10.5ns 0.0133 0 0 1.02 KB
master CallElasticsearchAsync net472 2.54μs 2.87ns 11.1ns 0.166 0 0 1.05 KB
#6183 CallElasticsearch net6.0 1.18μs 0.355ns 1.28ns 0.0136 0 0 976 B
#6183 CallElasticsearch netcoreapp3.1 1.52μs 0.86ns 3.22ns 0.0132 0 0 976 B
#6183 CallElasticsearch net472 2.58μs 2.9ns 11.2ns 0.158 0 0 995 B
#6183 CallElasticsearchAsync net6.0 1.21μs 0.51ns 1.98ns 0.0133 0 0 952 B
#6183 CallElasticsearchAsync netcoreapp3.1 1.62μs 0.653ns 2.44ns 0.0138 0 0 1.02 KB
#6183 CallElasticsearchAsync net472 2.79μs 2.2ns 8.53ns 0.167 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.22μs 0.898ns 3.48ns 0.0131 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.57μs 1.19ns 4.46ns 0.0126 0 0 952 B
master ExecuteAsync net472 1.78μs 0.4ns 1.5ns 0.145 0 0 915 B
#6183 ExecuteAsync net6.0 1.28μs 0.611ns 2.29ns 0.0135 0 0 952 B
#6183 ExecuteAsync netcoreapp3.1 1.63μs 0.865ns 3.35ns 0.0122 0 0 952 B
#6183 ExecuteAsync net472 1.82μs 0.806ns 3.12ns 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.31μs 3.58ns 13.4ns 0.0302 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.1μs 6.69ns 25.9ns 0.0358 0 0 2.76 KB
master SendAsync net472 7.81μs 5.89ns 22.8ns 0.497 0 0 3.15 KB
#6183 SendAsync net6.0 4.23μs 2.52ns 9.41ns 0.0315 0 0 2.22 KB
#6183 SendAsync netcoreapp3.1 5.09μs 2.65ns 10.3ns 0.0383 0 0 2.76 KB
#6183 SendAsync net472 7.85μs 3.27ns 12.6ns 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.45μs 0.859ns 2.98ns 0.0232 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.26μs 1.78ns 6.43ns 0.0219 0 0 1.64 KB
master EnrichedLog net472 2.63μs 1.69ns 6.56ns 0.249 0 0 1.57 KB
#6183 EnrichedLog net6.0 1.53μs 4.76ns 18.4ns 0.0234 0 0 1.64 KB
#6183 EnrichedLog netcoreapp3.1 2.18μs 0.93ns 3.35ns 0.0218 0 0 1.64 KB
#6183 EnrichedLog net472 2.68μs 1.23ns 4.76ns 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 115μs 140ns 543ns 0.0574 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 122μs 127ns 492ns 0 0 0 4.28 KB
master EnrichedLog net472 151μs 198ns 767ns 0.682 0.227 0 4.46 KB
#6183 EnrichedLog net6.0 117μs 160ns 598ns 0 0 0 4.28 KB
#6183 EnrichedLog netcoreapp3.1 122μs 210ns 815ns 0 0 0 4.28 KB
#6183 EnrichedLog net472 152μs 115ns 444ns 0.674 0.225 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.91μs 1.31ns 5.09ns 0.0304 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.16μs 1.7ns 6.57ns 0.0291 0 0 2.2 KB
master EnrichedLog net472 4.85μs 1.62ns 6.26ns 0.319 0 0 2.02 KB
#6183 EnrichedLog net6.0 3.07μs 1.41ns 5.26ns 0.0309 0 0 2.2 KB
#6183 EnrichedLog netcoreapp3.1 4.21μs 9.42ns 35.3ns 0.0294 0 0 2.2 KB
#6183 EnrichedLog net472 4.81μs 1.31ns 4.89ns 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.38μs 0.438ns 1.7ns 0.0158 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.82μs 0.999ns 3.87ns 0.0156 0 0 1.14 KB
master SendReceive net472 2.12μs 0.776ns 3.01ns 0.183 0.00106 0 1.16 KB
#6183 SendReceive net6.0 1.47μs 1.12ns 4.33ns 0.0161 0 0 1.14 KB
#6183 SendReceive netcoreapp3.1 1.75μs 1.6ns 6.18ns 0.0152 0 0 1.14 KB
#6183 SendReceive net472 2.18μs 2.14ns 8.3ns 0.183 0.00108 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.69μs 4.88ns 17.6ns 0.0214 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.91μs 1.5ns 5.8ns 0.0216 0 0 1.65 KB
master EnrichedLog net472 4.44μs 0.951ns 3.43ns 0.322 0 0 2.04 KB
#6183 EnrichedLog net6.0 2.72μs 0.839ns 3.25ns 0.0218 0 0 1.6 KB
#6183 EnrichedLog netcoreapp3.1 3.87μs 1.74ns 6.27ns 0.0211 0 0 1.65 KB
#6183 EnrichedLog net472 4.39μs 7.55ns 29.3ns 0.322 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6183

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.137 446.05 392.31

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 446ns 0.361ns 1.4ns 0.00805 0 0 576 B
master StartFinishSpan netcoreapp3.1 595ns 0.515ns 1.99ns 0.00747 0 0 576 B
master StartFinishSpan net472 670ns 0.827ns 3.2ns 0.0918 0 0 578 B
master StartFinishScope net6.0 509ns 0.292ns 1.13ns 0.00971 0 0 696 B
master StartFinishScope netcoreapp3.1 711ns 1.1ns 4.24ns 0.00918 0 0 696 B
master StartFinishScope net472 881ns 0.806ns 3.12ns 0.104 0 0 658 B
#6183 StartFinishSpan net6.0 392ns 0.346ns 1.34ns 0.00809 0 0 576 B
#6183 StartFinishSpan netcoreapp3.1 592ns 0.49ns 1.9ns 0.00796 0 0 576 B
#6183 StartFinishSpan net472 671ns 0.549ns 2.13ns 0.0916 0 0 578 B
#6183 StartFinishScope net6.0 551ns 0.472ns 1.83ns 0.00976 0 0 696 B
#6183 StartFinishScope netcoreapp3.1 723ns 0.443ns 1.71ns 0.00913 0 0 696 B
#6183 StartFinishScope net472 857ns 1.05ns 4.07ns 0.105 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 651ns 0.612ns 2.21ns 0.00967 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 977ns 0.873ns 3.38ns 0.0093 0 0 696 B
master RunOnMethodBegin net472 1.13μs 1.27ns 4.92ns 0.105 0 0 658 B
#6183 RunOnMethodBegin net6.0 667ns 1.07ns 4.13ns 0.00979 0 0 696 B
#6183 RunOnMethodBegin netcoreapp3.1 944ns 0.825ns 2.97ns 0.00928 0 0 696 B
#6183 RunOnMethodBegin net472 1.18μs 0.768ns 2.97ns 0.104 0 0 658 B

andrewlock avatar Oct 23 '24 10:10 andrewlock