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

[Dynamic Instrumentation] DEBUG-2916 Stabilize the probe processor

Open dudikeleti opened this issue 1 year ago • 4 comments

Summary of changes

This PR aims to fix various isue in the probe processor.

Implementation details

Any of the expressions (template, condition and metric) can be in an invalid state during the creation phase and compile\evaluation phase.

dudikeleti avatar Sep 25 '24 11:09 dudikeleti

Datadog Report

Branch report: dudik/nre-probeprocessor Commit report: fe872fe Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 456328 Passed, 3593 Skipped, 32h 27m 20.27s Total Time

datadog-ddstaging[bot] avatar Sep 25 '24 11:09 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 (6077) - mean (72ms)  : 63, 81
     .   : milestone, 72,
    master - mean (71ms)  : 65, 77
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (6077) - mean (1,111ms)  : 1090, 1132
     .   : milestone, 1111,
    master - mean (1,106ms)  : 1082, 1131
     .   : milestone, 1106,


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

    section CallTarget+Inlining+NGEN
    This PR (6077) - mean (769ms)  : 754, 785
     .   : milestone, 769,
    master - mean (773ms)  : 759, 788
     .   : milestone, 773,


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

    section CallTarget+Inlining+NGEN
    This PR (6077) - mean (728ms)  : 709, 747
     .   : milestone, 728,
    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 (6077) - mean (191ms)  : 185, 196
     .   : milestone, 191,
    master - mean (190ms)  : 187, 194
     .   : milestone, 190,

    section CallTarget+Inlining+NGEN
    This PR (6077) - mean (1,222ms)  : 1137, 1307
     .   : milestone, 1222,
    master - mean (1,227ms)  : 1201, 1254
     .   : milestone, 1227,


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

    section CallTarget+Inlining+NGEN
    This PR (6077) - mean (947ms)  : 924, 970
     .   : milestone, 947,
    master - mean (945ms)  : 919, 971
     .   : milestone, 945,


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

    section CallTarget+Inlining+NGEN
    This PR (6077) - mean (927ms)  : 908, 946
     .   : milestone, 927,
    master - mean (929ms)  : 914, 945
     .   : milestone, 929,

andrewlock avatar Sep 25 '24 11:09 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #6077 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.165
  • 1 benchmarks are slower, with geometric mean 1.206
  • 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.06μs 45.4ns 318ns 0.0203 0.00814 0 5.61 KB
master StartStopWithChild netcoreapp3.1 10.2μs 56.7ns 372ns 0.0193 0.00963 0 5.81 KB
master StartStopWithChild net472 16.5μs 80ns 320ns 1.05 0.312 0.107 6.22 KB
#6077 StartStopWithChild net6.0 7.99μs 45.5ns 318ns 0.0192 0.00768 0 5.61 KB
#6077 StartStopWithChild netcoreapp3.1 9.89μs 53.7ns 304ns 0.0192 0.00958 0 5.8 KB
#6077 StartStopWithChild net472 16.4μs 42ns 163ns 1.04 0.302 0.0979 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 488μs 234ns 876ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 634μs 295ns 1.06μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 843μs 784ns 3.04μs 0.422 0 0 3.3 KB
#6077 WriteAndFlushEnrichedTraces net6.0 477μs 850ns 3.29μs 0 0 0 2.7 KB
#6077 WriteAndFlushEnrichedTraces netcoreapp3.1 657μs 377ns 1.36μs 0 0 0 2.7 KB
#6077 WriteAndFlushEnrichedTraces net472 843μs 380ns 1.37μ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 200μs 1.11μs 8.3μs 0.188 0 0 18.73 KB
master SendRequest netcoreapp3.1 220μs 1.24μs 8.01μs 0.207 0 0 20.89 KB
master SendRequest net472 0ns 0ns 0ns 0 0 0 0 b
#6077 SendRequest net6.0 201μs 1.14μs 8.39μs 0.191 0 0 18.73 KB
#6077 SendRequest netcoreapp3.1 220μs 1.24μs 8.31μs 0.207 0 0 20.89 KB
#6077 SendRequest net472 0.0036ns 0.000834ns 0.00323ns 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 560μs 3.03μs 16μs 0.561 0 0 41.47 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 698μs 3.9μs 24μs 0.334 0 0 41.77 KB
master WriteAndFlushEnrichedTraces net472 864μs 3.06μs 11.9μs 8.33 2.5 0.417 53.33 KB
#6077 WriteAndFlushEnrichedTraces net6.0 566μs 2.6μs 10.1μs 0.563 0 0 41.46 KB
#6077 WriteAndFlushEnrichedTraces netcoreapp3.1 666μs 2.8μs 10.8μs 0.34 0 0 41.72 KB
#6077 WriteAndFlushEnrichedTraces net472 882μs 3.58μs 13.4μs 8.25 2.6 0.434 53.35 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.33μs 0.978ns 3.66ns 0.0146 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.79μs 1.56ns 6.04ns 0.014 0 0 1.02 KB
master ExecuteNonQuery net472 2.17μs 1.26ns 4.73ns 0.156 0.0011 0 987 B
#6077 ExecuteNonQuery net6.0 1.31μs 1.41ns 5.26ns 0.0145 0 0 1.02 KB
#6077 ExecuteNonQuery netcoreapp3.1 1.66μs 1.56ns 5.86ns 0.0133 0 0 1.02 KB
#6077 ExecuteNonQuery net472 2.09μs 1.52ns 5.88ns 0.156 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.26μs 0.819ns 3.17ns 0.0139 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.55μs 0.657ns 2.55ns 0.0125 0 0 976 B
master CallElasticsearch net472 2.44μs 1.37ns 5.12ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.36μs 0.645ns 2.5ns 0.0128 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.63μs 0.758ns 2.73ns 0.0139 0 0 1.02 KB
master CallElasticsearchAsync net472 2.68μs 1.5ns 5.81ns 0.166 0 0 1.05 KB
#6077 CallElasticsearch net6.0 1.27μs 0.809ns 3.03ns 0.0134 0 0 976 B
#6077 CallElasticsearch netcoreapp3.1 1.55μs 1.46ns 5.27ns 0.0132 0 0 976 B
#6077 CallElasticsearch net472 2.43μs 2.05ns 7.94ns 0.158 0 0 995 B
#6077 CallElasticsearchAsync net6.0 1.32μs 0.547ns 2.05ns 0.0132 0 0 952 B
#6077 CallElasticsearchAsync netcoreapp3.1 1.57μs 1.55ns 5.81ns 0.0141 0 0 1.02 KB
#6077 CallElasticsearchAsync net472 2.59μs 0.683ns 2.65ns 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.36μs 0.87ns 3.26ns 0.0131 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.67μs 0.923ns 3.45ns 0.0133 0 0 952 B
master ExecuteAsync net472 1.85μs 1.08ns 4.03ns 0.145 0 0 915 B
#6077 ExecuteAsync net6.0 1.25μs 0.4ns 1.5ns 0.0131 0 0 952 B
#6077 ExecuteAsync netcoreapp3.1 1.77μs 0.722ns 2.6ns 0.0125 0 0 952 B
#6077 ExecuteAsync net472 1.78μs 0.627ns 2.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.42μs 2.82ns 10.9ns 0.033 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.42μs 2.45ns 9.18ns 0.0379 0 0 2.85 KB
master SendAsync net472 7.46μs 5.19ns 20.1ns 0.493 0 0 3.12 KB
#6077 SendAsync net6.0 4.67μs 2.44ns 9.14ns 0.0326 0 0 2.31 KB
#6077 SendAsync netcoreapp3.1 5.38μs 1.65ns 6.39ns 0.0376 0 0 2.85 KB
#6077 SendAsync net472 7.64μs 1.87ns 6.73ns 0.494 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.46μs 0.671ns 2.51ns 0.0233 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.17μs 0.663ns 2.39ns 0.0227 0 0 1.64 KB
master EnrichedLog net472 2.69μs 1.6ns 6.21ns 0.249 0 0 1.57 KB
#6077 EnrichedLog net6.0 1.57μs 0.888ns 3.32ns 0.0229 0 0 1.64 KB
#6077 EnrichedLog netcoreapp3.1 2.22μs 0.954ns 3.57ns 0.0222 0 0 1.64 KB
#6077 EnrichedLog net472 2.64μs 1.21ns 4.67ns 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 119μs 237ns 917ns 0.0594 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 123μs 335ns 1.3μs 0 0 0 4.28 KB
master EnrichedLog net472 154μs 150ns 581ns 0.691 0.23 0 4.46 KB
#6077 EnrichedLog net6.0 116μs 235ns 911ns 0.0576 0 0 4.28 KB
#6077 EnrichedLog netcoreapp3.1 123μs 136ns 510ns 0 0 0 4.28 KB
#6077 EnrichedLog net472 155μs 158ns 614ns 0.694 0.231 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.04μs 0.741ns 2.77ns 0.0305 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.05μs 2.19ns 7.88ns 0.0287 0 0 2.2 KB
master EnrichedLog net472 4.82μs 1.67ns 6.26ns 0.32 0 0 2.02 KB
#6077 EnrichedLog net6.0 2.89μs 1.02ns 3.8ns 0.0305 0 0 2.2 KB
#6077 EnrichedLog netcoreapp3.1 4.04μs 1.48ns 5.54ns 0.0303 0 0 2.2 KB
#6077 EnrichedLog net472 4.73μs 1.68ns 6.49ns 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.28μs 1.23ns 4.78ns 0.0161 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.85μs 0.78ns 3.02ns 0.0157 0 0 1.14 KB
master SendReceive net472 2.13μs 2.09ns 7.22ns 0.184 0 0 1.16 KB
#6077 SendReceive net6.0 1.35μs 0.796ns 3.08ns 0.0162 0 0 1.14 KB
#6077 SendReceive netcoreapp3.1 1.86μs 0.778ns 2.91ns 0.0158 0 0 1.14 KB
#6077 SendReceive net472 2.13μs 1.17ns 4.52ns 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.67μs 0.987ns 3.69ns 0.0227 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.68μs 2.71ns 10.5ns 0.0221 0 0 1.65 KB
master EnrichedLog net472 4.35μs 1.81ns 6.78ns 0.322 0 0 2.04 KB
#6077 EnrichedLog net6.0 2.81μs 0.616ns 2.22ns 0.0226 0 0 1.6 KB
#6077 EnrichedLog netcoreapp3.1 3.82μs 1.83ns 6.85ns 0.0209 0 0 1.65 KB
#6077 EnrichedLog net472 4.31μs 1.61ns 6.22ns 0.323 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #6077

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.206 403.32 486.32

Faster :tada: in #6077

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 1.217 668.85 549.51
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1 1.115 789.71 708.20

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 403ns 0.158ns 0.592ns 0.0081 0 0 576 B
master StartFinishSpan netcoreapp3.1 664ns 2.96ns 11.5ns 0.00776 0 0 576 B
master StartFinishSpan net472 718ns 0.792ns 3.07ns 0.0917 0 0 578 B
master StartFinishScope net6.0 475ns 0.58ns 2.25ns 0.00968 0 0 696 B
master StartFinishScope netcoreapp3.1 790ns 0.64ns 2.48ns 0.00911 0 0 696 B
master StartFinishScope net472 902ns 0.888ns 3.44ns 0.104 0 0 658 B
#6077 StartFinishSpan net6.0 486ns 0.326ns 1.26ns 0.00807 0 0 576 B
#6077 StartFinishSpan netcoreapp3.1 549ns 0.43ns 1.55ns 0.0077 0 0 576 B
#6077 StartFinishSpan net472 723ns 0.81ns 3.14ns 0.0917 0 0 578 B
#6077 StartFinishScope net6.0 499ns 0.436ns 1.69ns 0.00981 0 0 696 B
#6077 StartFinishScope netcoreapp3.1 708ns 0.848ns 3.17ns 0.00917 0 0 696 B
#6077 StartFinishScope net472 894ns 1.13ns 4.39ns 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 667ns 0.484ns 1.87ns 0.00964 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 933ns 3.18ns 12.3ns 0.0095 0 0 696 B
master RunOnMethodBegin net472 1.15μs 0.798ns 3.09ns 0.104 0 0 658 B
#6077 RunOnMethodBegin net6.0 717ns 0.711ns 2.75ns 0.00979 0 0 696 B
#6077 RunOnMethodBegin netcoreapp3.1 876ns 0.74ns 2.87ns 0.00925 0 0 696 B
#6077 RunOnMethodBegin net472 1.22μs 0.485ns 1.88ns 0.104 0 0 658 B

andrewlock avatar Sep 25 '24 12: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 (6077) (11.233M)   : 0, 11232671
    master (11.174M)   : 0, 11173945
    benchmarks/2.9.0 (11.033M)   : 0, 11032866

    section Automatic
    This PR (6077) (7.274M)   : 0, 7273653
    master (7.312M)   : 0, 7312280
    benchmarks/2.9.0 (7.786M)   : 0, 7785853

    section Trace stats
    master (7.553M)   : 0, 7553254

    section Manual
    master (11.102M)   : 0, 11101684

    section Manual + Automatic
    This PR (6077) (6.768M)   : 0, 6768003
    master (6.740M)   : 0, 6739647

    section DD_TRACE_ENABLED=0
    master (10.282M)   : 0, 10282028


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6077) (9.586M)   : 0, 9585683
    master (9.530M)   : 0, 9530431
    benchmarks/2.9.0 (9.495M)   : 0, 9494821

    section Automatic
    This PR (6077) (6.370M)   : 0, 6370359
    master (6.395M)   : 0, 6394628

    section Trace stats
    master (6.680M)   : 0, 6679934

    section Manual
    master (9.631M)   : 0, 9630609

    section Manual + Automatic
    This PR (6077) (6.182M)   : 0, 6181721
    master (5.995M)   : 0, 5995215

    section DD_TRACE_ENABLED=0
    master (8.922M)   : 0, 8921645


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6077) (9.871M)   : 0, 9870687
    master (9.758M)   : 0, 9758058
    benchmarks/2.9.0 (10.020M)   : 0, 10019592

    section Automatic
    This PR (6077) (6.611M)   : 0, 6610991
    master (6.513M)   : 0, 6512759
    benchmarks/2.9.0 (7.255M)   : 0, 7255257

    section Trace stats
    master (7.074M)   : 0, 7073637

    section Manual
    master (9.827M)   : 0, 9827350

    section Manual + Automatic
    This PR (6077) (5.930M)   : 0, 5929593
    master (5.944M)   : 0, 5943752

    section DD_TRACE_ENABLED=0
    master (9.348M)   : 0, 9348488

andrewlock avatar Sep 25 '24 13:09 andrewlock