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

Fayssal/setup macrobenchmarks

Open faydef opened this issue 1 year ago • 4 comments

Summary of changes

Adding macrobenchmarks for the dotnet tracer

Reason for change

Visibility on impact of our tracers on clients' applications

Implementation details

Test coverage

Other details

faydef avatar Sep 16 '24 11:09 faydef

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 (6035) - mean (72ms)  : 66, 77
     .   : milestone, 72,
    master - mean (73ms)  : 66, 79
     .   : milestone, 73,

    section CallTarget+Inlining+NGEN
    This PR (6035) - mean (1,109ms)  : 1080, 1138
     .   : milestone, 1109,
    master - mean (1,109ms)  : 1080, 1138
     .   : milestone, 1109,


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

    section CallTarget+Inlining+NGEN
    This PR (6035) - mean (792ms)  : 721, 863
     .   : milestone, 792,
    master - mean (777ms)  : 753, 802
     .   : milestone, 777,


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

    section CallTarget+Inlining+NGEN
    This PR (6035) - mean (745ms)  : 706, 785
     .   : milestone, 745,
    master - mean (734ms)  : 713, 755
     .   : milestone, 734,


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

    section CallTarget+Inlining+NGEN
    This PR (6035) - mean (1,196ms)  : 1174, 1218
     .   : milestone, 1196,
    master - mean (1,195ms)  : 1171, 1219
     .   : milestone, 1195,


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

    section CallTarget+Inlining+NGEN
    This PR (6035) - mean (939ms)  : 920, 959
     .   : milestone, 939,
    master - mean (936ms)  : 921, 951
     .   : milestone, 936,


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

    section CallTarget+Inlining+NGEN
    This PR (6035) - mean (925ms)  : 911, 938
     .   : milestone, 925,
    master - mean (931ms)  : 902, 960
     .   : milestone, 931,

andrewlock avatar Sep 16 '24 12:09 andrewlock

Datadog Report

Branch report: fayssal/setup-macrobenchmarks Commit report: cd41c9b Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 362785 Passed, 2084 Skipped, 15h 28m 21.45s Total Time :hourglass: 1 Performance Regression

:hourglass: Performance Regressions vs Default Branch (1)

  • StartStopWithChild - Benchmarks.Trace.ActivityBenchmark 16.66µs (+616ns, +4%) - Details

datadog-ddstaging[bot] avatar Sep 16 '24 12:09 datadog-ddstaging[bot]

Benchmarks Report for tracer :snail:

Benchmarks for #6035 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.150
  • 3 benchmarks are slower, with geometric mean 1.213
  • 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 41ns 232ns 0.0204 0.00816 0 5.43 KB
master StartStopWithChild netcoreapp3.1 10.1μs 55.3ns 336ns 0.0146 0.00486 0 5.62 KB
master StartStopWithChild net472 16.3μs 71.4ns 277ns 1.02 0.302 0.0953 6.07 KB
#6035 StartStopWithChild net6.0 7.83μs 44.3ns 329ns 0.0125 0.00832 0 5.42 KB
#6035 StartStopWithChild netcoreapp3.1 9.89μs 52.9ns 285ns 0.0192 0.00961 0 5.62 KB
#6035 StartStopWithChild net472 16.7μs 91.6ns 557ns 1.01 0.293 0.0815 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 459μs 467ns 1.75μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 632μs 410ns 1.59μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 816μs 590ns 2.28μs 0.408 0 0 3.3 KB
#6035 WriteAndFlushEnrichedTraces net6.0 470μs 289ns 1.08μs 0 0 0 2.7 KB
#6035 WriteAndFlushEnrichedTraces netcoreapp3.1 652μs 247ns 922ns 0 0 0 2.7 KB
#6035 WriteAndFlushEnrichedTraces net472 837μs 404ns 1.57μs 0.417 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 195μs 1.07μs 7.85μs 0.188 0 0 18.45 KB
master SendRequest netcoreapp3.1 219μs 1.26μs 9.24μs 0.204 0 0 20.61 KB
master SendRequest net472 0.00322ns 0.00106ns 0.00409ns 0 0 0 0 b
#6035 SendRequest net6.0 192μs 1.04μs 6.31μs 0.196 0 0 18.45 KB
#6035 SendRequest netcoreapp3.1 223μs 1.24μs 11.1μs 0.21 0 0 20.61 KB
#6035 SendRequest net472 0.00119ns 0.000489ns 0.00183ns 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 567μs 2.59μs 9.7μs 0.561 0 0 41.58 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 694μs 3.74μs 19.8μs 0.331 0 0 41.7 KB
master WriteAndFlushEnrichedTraces net472 860μs 3.08μs 11.5μs 8.5 2.55 0.425 53.31 KB
#6035 WriteAndFlushEnrichedTraces net6.0 557μs 1.62μs 5.86μs 0.571 0 0 41.61 KB
#6035 WriteAndFlushEnrichedTraces netcoreapp3.1 673μs 3.38μs 17.9μs 0.327 0 0 41.83 KB
#6035 WriteAndFlushEnrichedTraces net472 866μs 4.46μs 20.9μs 8.39 2.52 0.419 53.27 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.25μs 1.32ns 5.13ns 0.0145 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.74μs 0.908ns 3.4ns 0.0132 0 0 1.02 KB
master ExecuteNonQuery net472 2.1μs 1.63ns 6.3ns 0.156 0 0 987 B
#6035 ExecuteNonQuery net6.0 1.33μs 1.08ns 4.04ns 0.014 0 0 1.02 KB
#6035 ExecuteNonQuery netcoreapp3.1 1.81μs 4.17ns 16.1ns 0.0132 0 0 1.02 KB
#6035 ExecuteNonQuery net472 2.03μs 1.59ns 6.14ns 0.157 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.19μs 2.72ns 10.5ns 0.0138 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.51μs 0.484ns 1.81ns 0.0128 0 0 976 B
master CallElasticsearch net472 2.55μs 2.83ns 11ns 0.158 0 0 995 B
master CallElasticsearchAsync net6.0 1.2μs 0.846ns 3.28ns 0.0131 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.7μs 0.992ns 3.71ns 0.0135 0 0 1.02 KB
master CallElasticsearchAsync net472 2.62μs 2.56ns 9.9ns 0.166 0 0 1.05 KB
#6035 CallElasticsearch net6.0 1.17μs 1.03ns 3.87ns 0.0137 0 0 976 B
#6035 CallElasticsearch netcoreapp3.1 1.51μs 1.01ns 3.92ns 0.013 0 0 976 B
#6035 CallElasticsearch net472 2.34μs 1.37ns 5.14ns 0.158 0 0 995 B
#6035 CallElasticsearchAsync net6.0 1.23μs 0.418ns 1.57ns 0.0135 0 0 952 B
#6035 CallElasticsearchAsync netcoreapp3.1 1.64μs 1.4ns 5.23ns 0.0141 0 0 1.02 KB
#6035 CallElasticsearchAsync net472 2.51μs 1.23ns 4.6ns 0.167 0 0 1.05 KB
Benchmarks.Trace.GraphQLBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6035

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0 1.150 1,384.54 1,203.91

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.38μs 0.977ns 3.65ns 0.0131 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.62μs 0.528ns 1.9ns 0.013 0 0 952 B
master ExecuteAsync net472 1.76μs 0.534ns 2.07ns 0.145 0 0 915 B
#6035 ExecuteAsync net6.0 1.2μs 0.615ns 2.38ns 0.0133 0 0 952 B
#6035 ExecuteAsync netcoreapp3.1 1.65μs 5.69ns 22ns 0.0128 0 0 952 B
#6035 ExecuteAsync net472 1.82μs 0.961ns 3.72ns 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.23μs 10.6ns 41.1ns 0.0317 0 0 2.22 KB
master SendAsync netcoreapp3.1 4.96μs 1.93ns 7.24ns 0.0372 0 0 2.76 KB
master SendAsync net472 7.66μs 2.95ns 11.4ns 0.499 0 0 3.15 KB
#6035 SendAsync net6.0 4.06μs 1.07ns 4ns 0.0309 0 0 2.22 KB
#6035 SendAsync netcoreapp3.1 5.06μs 1.8ns 6.73ns 0.0379 0 0 2.76 KB
#6035 SendAsync net472 7.73μs 1.99ns 7.72ns 0.497 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.53μs 0.952ns 3.69ns 0.0229 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.33μs 2.57ns 9.63ns 0.022 0 0 1.64 KB
master EnrichedLog net472 2.61μs 1.14ns 4.26ns 0.25 0 0 1.57 KB
#6035 EnrichedLog net6.0 1.59μs 0.945ns 3.41ns 0.0229 0 0 1.64 KB
#6035 EnrichedLog netcoreapp3.1 2.13μs 0.738ns 2.86ns 0.0222 0 0 1.64 KB
#6035 EnrichedLog net472 2.61μs 1.06ns 4.12ns 0.248 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 114μs 147ns 550ns 0.0571 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 118μs 240ns 928ns 0.0597 0 0 4.28 KB
master EnrichedLog net472 147μs 156ns 603ns 0.662 0.221 0 4.46 KB
#6035 EnrichedLog net6.0 111μs 101ns 390ns 0.0559 0 0 4.28 KB
#6035 EnrichedLog netcoreapp3.1 118μs 180ns 650ns 0 0 0 4.28 KB
#6035 EnrichedLog net472 146μs 110ns 426ns 0.653 0.218 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.22μs 1.67ns 6.46ns 0.0306 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.12μs 5.94ns 23ns 0.0286 0 0 2.2 KB
master EnrichedLog net472 4.75μs 2.03ns 7.86ns 0.32 0 0 2.02 KB
#6035 EnrichedLog net6.0 3.12μs 1.21ns 4.7ns 0.0312 0 0 2.2 KB
#6035 EnrichedLog netcoreapp3.1 4.28μs 2.66ns 9.22ns 0.0282 0 0 2.2 KB
#6035 EnrichedLog net472 4.98μs 1.91ns 7.41ns 0.319 0 0 2.02 KB
Benchmarks.Trace.RedisBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6035

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.RedisBenchmark.SendReceive‑net6.0 1.160 1,269.14 1,471.78

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net6.0 1.27μs 0.633ns 2.37ns 0.0159 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.76μs 0.651ns 2.52ns 0.015 0 0 1.14 KB
master SendReceive net472 2.07μs 0.948ns 3.55ns 0.183 0 0 1.16 KB
#6035 SendReceive net6.0 1.48μs 2.28ns 8.83ns 0.0156 0 0 1.14 KB
#6035 SendReceive netcoreapp3.1 1.8μs 1.8ns 6.98ns 0.0153 0 0 1.14 KB
#6035 SendReceive net472 1.98μs 0.922ns 3.57ns 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 EnrichedLog net6.0 2.81μs 0.942ns 3.65ns 0.0224 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.88μs 2.39ns 9.27ns 0.0215 0 0 1.65 KB
master EnrichedLog net472 4.31μs 2.81ns 10.9ns 0.323 0 0 2.04 KB
#6035 EnrichedLog net6.0 2.81μs 1.15ns 4.14ns 0.0213 0 0 1.6 KB
#6035 EnrichedLog netcoreapp3.1 3.91μs 0.888ns 3.44ns 0.0216 0 0 1.65 KB
#6035 EnrichedLog net472 4.36μs 1.34ns 5.02ns 0.323 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6035

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 1.154 542.02 625.68

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 399ns 0.421ns 1.63ns 0.00818 0 0 576 B
master StartFinishSpan netcoreapp3.1 541ns 0.532ns 2.06ns 0.00794 0 0 576 B
master StartFinishSpan net472 735ns 0.366ns 1.42ns 0.0916 0 0 578 B
master StartFinishScope net6.0 471ns 0.411ns 1.59ns 0.00971 0 0 696 B
master StartFinishScope netcoreapp3.1 729ns 0.285ns 1.1ns 0.00918 0 0 696 B
master StartFinishScope net472 894ns 1.61ns 6.23ns 0.104 0 0 658 B
#6035 StartFinishSpan net6.0 409ns 0.348ns 1.35ns 0.00807 0 0 576 B
#6035 StartFinishSpan netcoreapp3.1 626ns 0.36ns 1.35ns 0.00777 0 0 576 B
#6035 StartFinishSpan net472 741ns 3.16ns 12.2ns 0.0915 0 0 578 B
#6035 StartFinishScope net6.0 474ns 0.798ns 3.09ns 0.00985 0 0 696 B
#6035 StartFinishScope netcoreapp3.1 700ns 3.88ns 23.3ns 0.00952 0 0 696 B
#6035 StartFinishScope net472 927ns 2.57ns 9.6ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6035

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 1.334 605.92 808.16

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 606ns 0.269ns 1.01ns 0.00975 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 848ns 0.522ns 1.81ns 0.00937 0 0 696 B
master RunOnMethodBegin net472 1.02μs 0.635ns 2.46ns 0.104 0 0 658 B
#6035 RunOnMethodBegin net6.0 809ns 0.925ns 3.46ns 0.00973 0 0 696 B
#6035 RunOnMethodBegin netcoreapp3.1 901ns 0.484ns 1.87ns 0.00949 0 0 696 B
#6035 RunOnMethodBegin net472 1.11μs 4.04ns 15.6ns 0.104 0 0 658 B

andrewlock avatar Sep 16 '24 14:09 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 (6035) (11.094M)   : 0, 11094366
    master (11.066M)   : 0, 11065553
    benchmarks/2.9.0 (11.081M)   : 0, 11080577

    section Automatic
    This PR (6035) (7.377M)   : 0, 7377141
    master (7.168M)   : 0, 7168396
    benchmarks/2.9.0 (7.732M)   : 0, 7732233

    section Trace stats
    master (7.603M)   : 0, 7602954

    section Manual
    master (10.985M)   : 0, 10984631

    section Manual + Automatic
    This PR (6035) (6.790M)   : 0, 6790223
    master (6.859M)   : 0, 6858527

    section DD_TRACE_ENABLED=0
    master (10.326M)   : 0, 10326279


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6035) (9.429M)   : 0, 9429378
    master (9.502M)   : 0, 9501909
    benchmarks/2.9.0 (9.798M)   : 0, 9798067

    section Automatic
    This PR (6035) (6.562M)   : 0, 6561543
    master (6.547M)   : 0, 6547161

    section Trace stats
    master (6.970M)   : 0, 6970237

    section Manual
    master (9.184M)   : 0, 9184289

    section Manual + Automatic
    This PR (6035) (5.997M)   : 0, 5997324
    master (6.133M)   : 0, 6132723

    section DD_TRACE_ENABLED=0
    master (8.818M)   : 0, 8818202


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6035) (10.262M)   : 0, 10261597
    master (10.130M)   : 0, 10129657
    benchmarks/2.9.0 (10.067M)   : 0, 10067315

    section Automatic
    This PR (6035) (6.747M)   : 0, 6747233
    master (6.591M)   : 0, 6591169
    benchmarks/2.9.0 (7.552M)   : 0, 7552193

    section Trace stats
    master (7.357M)   : 0, 7357388

    section Manual
    master (10.018M)   : 0, 10018296

    section Manual + Automatic
    This PR (6035) (6.347M)   : 0, 6347303
    master (6.057M)   : 0, 6056873

    section DD_TRACE_ENABLED=0
    master (9.433M)   : 0, 9433366

andrewlock avatar Sep 16 '24 14:09 andrewlock

Superseded by #6765

andrewlock avatar May 01 '25 10:05 andrewlock