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

tony/manual-instrumentation-ngen-support

Open tonyredondo opened this issue 11 months ago • 3 comments

Summary of changes

Reason for change

Implementation details

Test coverage

Other details

tonyredondo avatar Jan 24 '25 22:01 tonyredondo

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 (6593) - mean (69ms)  : 66, 72
     .   : milestone, 69,
    master - mean (70ms)  : 65, 75
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (6593) - mean (1,049ms)  : 1025, 1072
     .   : milestone, 1049,
    master - mean (1,028ms)  : 1010, 1046
     .   : milestone, 1028,

gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6593) - mean (108ms)  : 102, 114
     .   : milestone, 108,
    master - mean (117ms)  : 99, 136
     .   : milestone, 117,

    section CallTarget+Inlining+NGEN
    This PR (6593) - mean (763ms)  : 751, 774
     .   : milestone, 763,
    master - mean (730ms)  : 714, 746
     .   : milestone, 730,

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

    section CallTarget+Inlining+NGEN
    This PR (6593) - mean (711ms)  : 695, 727
     .   : milestone, 711,
    master - mean (681ms)  : 657, 704
     .   : milestone, 681,

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

    section CallTarget+Inlining+NGEN
    This PR (6593) - mean (1,153ms)  : 1124, 1181
     .   : milestone, 1153,
    master - mean (1,136ms)  : 1106, 1166
     .   : milestone, 1136,

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

    section CallTarget+Inlining+NGEN
    This PR (6593) - mean (951ms)  : 928, 974
     .   : milestone, 951,
    master - mean (919ms)  : 889, 948
     .   : milestone, 919,

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

    section CallTarget+Inlining+NGEN
    This PR (6593) - mean (922ms)  : 895, 949
     .   : milestone, 922,
    master - mean (891ms)  : 857, 925
     .   : milestone, 891,

andrewlock avatar Jan 24 '25 23:01 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #6593 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.122
  • 3 benchmarks are slower, with geometric mean 1.178
  • 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.95μs 44.4ns 277ns 0.0155 0.00387 0 5.61 KB
master StartStopWithChild netcoreapp3.1 10.3μs 57.5ns 345ns 0.0153 0.00511 0 5.8 KB
master StartStopWithChild net472 16.1μs 59.6ns 231ns 1.05 0.305 0.102 6.21 KB
#6593 StartStopWithChild net6.0 8.17μs 45.1ns 278ns 0.0166 0.00829 0 5.61 KB
#6593 StartStopWithChild netcoreapp3.1 10.1μs 55.5ns 309ns 0.0207 0.00516 0 5.8 KB
#6593 StartStopWithChild net472 15.9μs 49.6ns 185ns 1.05 0.306 0.0943 6.21 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 494μs 338ns 1.31μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 652μs 214ns 773ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 871μs 514ns 1.92μs 0.434 0 0 3.3 KB
#6593 WriteAndFlushEnrichedTraces net6.0 499μs 293ns 1.14μs 0 0 0 2.7 KB
#6593 WriteAndFlushEnrichedTraces netcoreapp3.1 659μs 360ns 1.39μs 0 0 0 2.7 KB
#6593 WriteAndFlushEnrichedTraces net472 862μs 415ns 1.55μs 0.431 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 128μs 367ns 1.37μs 0.195 0 0 14.47 KB
master SendRequest netcoreapp3.1 141μs 531ns 2.06μs 0.209 0 0 17.27 KB
master SendRequest net472 0.000595ns 0.000595ns 0.00223ns 0 0 0 0 b
#6593 SendRequest net6.0 127μs 486ns 1.82μs 0.133 0 0 14.47 KB
#6593 SendRequest netcoreapp3.1 142μs 492ns 1.9μs 0.212 0 0 17.27 KB
#6593 SendRequest net472 0.00197ns 0.000896ns 0.00347ns 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 566μs 2.54μs 9.5μs 0.571 0 0 41.77 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 664μs 3.5μs 18.2μs 0.322 0 0 41.78 KB
master WriteAndFlushEnrichedTraces net472 840μs 3.37μs 12.6μs 8.39 2.52 0.419 53.35 KB
#6593 WriteAndFlushEnrichedTraces net6.0 561μs 2.98μs 14.9μs 0.543 0 0 41.58 KB
#6593 WriteAndFlushEnrichedTraces netcoreapp3.1 640μs 1.99μs 7.95μs 0.319 0 0 41.67 KB
#6593 WriteAndFlushEnrichedTraces net472 834μs 2.86μs 11.1μs 8.33 2.5 0.417 53.3 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.39μs 0.896ns 3.35ns 0.0147 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.69μs 1.3ns 4.87ns 0.0136 0 0 1.02 KB
master ExecuteNonQuery net472 2μs 1.82ns 7.03ns 0.157 0.001 0 987 B
#6593 ExecuteNonQuery net6.0 1.31μs 1.64ns 6.36ns 0.0145 0 0 1.02 KB
#6593 ExecuteNonQuery netcoreapp3.1 1.74μs 1.08ns 4.19ns 0.014 0 0 1.02 KB
#6593 ExecuteNonQuery net472 2.06μs 1.56ns 6.04ns 0.157 0.00105 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6593

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearch‑netcoreapp3.1 1.122 1,666.55 1,485.95

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.24μs 0.5ns 1.87ns 0.0137 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.67μs 0.895ns 3.46ns 0.0125 0 0 976 B
master CallElasticsearch net472 2.66μs 2.07ns 8ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.32μs 0.454ns 1.7ns 0.0133 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.64μs 0.673ns 2.52ns 0.014 0 0 1.02 KB
master CallElasticsearchAsync net472 2.67μs 2.29ns 8.86ns 0.167 0 0 1.05 KB
#6593 CallElasticsearch net6.0 1.29μs 1.02ns 3.83ns 0.0137 0 0 976 B
#6593 CallElasticsearch netcoreapp3.1 1.49μs 0.754ns 2.82ns 0.0134 0 0 976 B
#6593 CallElasticsearch net472 2.57μs 2.17ns 8.42ns 0.157 0 0 995 B
#6593 CallElasticsearchAsync net6.0 1.27μs 0.801ns 3.1ns 0.0132 0 0 952 B
#6593 CallElasticsearchAsync netcoreapp3.1 1.65μs 0.593ns 2.3ns 0.014 0 0 1.02 KB
#6593 CallElasticsearchAsync net472 2.77μs 1.59ns 6.16ns 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.28μs 0.543ns 1.88ns 0.0134 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.63μs 0.778ns 2.81ns 0.0132 0 0 952 B
master ExecuteAsync net472 1.85μs 0.695ns 2.6ns 0.145 0 0 915 B
#6593 ExecuteAsync net6.0 1.28μs 0.698ns 2.52ns 0.0136 0 0 952 B
#6593 ExecuteAsync netcoreapp3.1 1.59μs 0.885ns 3.31ns 0.0127 0 0 952 B
#6593 ExecuteAsync net472 1.84μs 0.682ns 2.64ns 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.41μs 0.97ns 3.76ns 0.031 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.39μs 1.33ns 4.99ns 0.0377 0 0 2.85 KB
master SendAsync net472 7.45μs 1.34ns 5.18ns 0.494 0 0 3.12 KB
#6593 SendAsync net6.0 4.34μs 1.23ns 4.76ns 0.0325 0 0 2.31 KB
#6593 SendAsync netcoreapp3.1 5.37μs 12.8ns 47.8ns 0.037 0 0 2.85 KB
#6593 SendAsync net472 7.42μs 1.35ns 5.22ns 0.493 0 0 3.12 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.5μs 1.33ns 4.99ns 0.0226 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.35μs 5.13ns 19.9ns 0.0218 0 0 1.64 KB
master EnrichedLog net472 2.66μs 0.761ns 2.85ns 0.249 0 0 1.57 KB
#6593 EnrichedLog net6.0 1.49μs 1.78ns 6.65ns 0.0225 0 0 1.64 KB
#6593 EnrichedLog netcoreapp3.1 2.23μs 1.67ns 6.01ns 0.0222 0 0 1.64 KB
#6593 EnrichedLog net472 2.65μs 0.685ns 2.56ns 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 129ns 499ns 0.0579 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 119μs 66.6ns 249ns 0 0 0 4.28 KB
master EnrichedLog net472 152μs 130ns 502ns 0.686 0.229 0 4.46 KB
#6593 EnrichedLog net6.0 116μs 175ns 677ns 0.0578 0 0 4.28 KB
#6593 EnrichedLog netcoreapp3.1 119μs 84.4ns 304ns 0 0 0 4.28 KB
#6593 EnrichedLog net472 150μs 122ns 473ns 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 3.1μs 1.21ns 4.69ns 0.0311 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.3μs 2.18ns 8.44ns 0.028 0 0 2.2 KB
master EnrichedLog net472 5.1μs 1.49ns 5.78ns 0.321 0 0 2.02 KB
#6593 EnrichedLog net6.0 3.03μs 0.686ns 2.66ns 0.0303 0 0 2.2 KB
#6593 EnrichedLog netcoreapp3.1 4.12μs 1.69ns 6.53ns 0.0293 0 0 2.2 KB
#6593 EnrichedLog net472 5μs 1.3ns 5.04ns 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.26μs 0.549ns 2.05ns 0.0164 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.86μs 0.528ns 1.98ns 0.0155 0 0 1.14 KB
master SendReceive net472 2.18μs 1.01ns 3.91ns 0.183 0 0 1.16 KB
#6593 SendReceive net6.0 1.28μs 0.567ns 2.12ns 0.016 0 0 1.14 KB
#6593 SendReceive netcoreapp3.1 1.78μs 1.01ns 3.93ns 0.0152 0 0 1.14 KB
#6593 SendReceive net472 2.07μs 0.81ns 3.14ns 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.61μs 1.18ns 4.4ns 0.0221 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 4.24μs 0.896ns 3.47ns 0.021 0 0 1.65 KB
master EnrichedLog net472 4.52μs 3.83ns 14.8ns 0.323 0 0 2.04 KB
#6593 EnrichedLog net6.0 2.67μs 1.43ns 5.55ns 0.0227 0 0 1.6 KB
#6593 EnrichedLog netcoreapp3.1 3.95μs 1.82ns 6.32ns 0.0218 0 0 1.65 KB
#6593 EnrichedLog net472 4.52μs 3.11ns 11.6ns 0.322 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6593

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.150 397.38 456.84
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 1.135 484.10 549.56

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 397ns 1.01ns 3.93ns 0.00801 0 0 576 B
master StartFinishSpan netcoreapp3.1 604ns 1.15ns 4.47ns 0.00767 0 0 576 B
master StartFinishSpan net472 617ns 1.15ns 4.45ns 0.0915 0 0 578 B
master StartFinishScope net6.0 484ns 0.921ns 3.57ns 0.00973 0 0 696 B
master StartFinishScope netcoreapp3.1 713ns 0.801ns 3ns 0.00972 0 0 696 B
master StartFinishScope net472 899ns 1.5ns 5.42ns 0.104 0 0 658 B
#6593 StartFinishSpan net6.0 457ns 0.742ns 2.87ns 0.00802 0 0 576 B
#6593 StartFinishSpan netcoreapp3.1 637ns 1.68ns 6.52ns 0.00775 0 0 576 B
#6593 StartFinishSpan net472 563ns 1.04ns 4.04ns 0.0917 0 0 578 B
#6593 StartFinishScope net6.0 549ns 0.33ns 1.28ns 0.00983 0 0 696 B
#6593 StartFinishScope netcoreapp3.1 687ns 1.42ns 5.51ns 0.00926 0 0 696 B
#6593 StartFinishScope net472 840ns 1.53ns 5.72ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6593

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 1.252 598.54 749.16

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 598ns 0.898ns 3.48ns 0.00987 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 936ns 1.87ns 7.23ns 0.00938 0 0 696 B
master RunOnMethodBegin net472 1.03μs 1.94ns 7.52ns 0.105 0 0 658 B
#6593 RunOnMethodBegin net6.0 749ns 1.35ns 5.22ns 0.00961 0 0 696 B
#6593 RunOnMethodBegin netcoreapp3.1 964ns 0.858ns 3.32ns 0.00942 0 0 696 B
#6593 RunOnMethodBegin net472 1.08μs 1.25ns 4.68ns 0.104 0 0 658 B

andrewlock avatar Jan 24 '25 23:01 andrewlock

Datadog Report

Branch report: tony/manual-instrumentation-ngen-support Commit report: 36eaa92 Test service: dd-trace-dotnet

:x: 2 Failed (0 Known Flaky), 247961 Passed, 2919 Skipped, 32h 50m 31.59s Total Time

:x: Failed Tests (2)

  • NGenRunManualAndAutomatic - Datadog.Trace.ClrProfiler.IntegrationTests.ManualInstrumentationTests - Details

    Expand for error
    xpected exit code: 0, actual exit code: -532462766.
    
  • NGenRunManualAndAutomatic - Datadog.Trace.ClrProfiler.IntegrationTests.ManualInstrumentationTests - Details

    Expand for error
    xpected exit code: 0, actual exit code: -2146233082.
    

datadog-ddstaging[bot] avatar Jan 25 '25 00:01 datadog-ddstaging[bot]