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

[Dynamic Instrumentation] Fix line exploration tests

Open dudikeleti opened this issue 1 year ago • 5 comments

Summary of changes

Line exploration tests should run for now only for protobuf

dudikeleti avatar Sep 26 '24 15:09 dudikeleti

Datadog Report

Branch report: dudik/fix-line-exploration-tests Commit report: 9923282 Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 372338 Passed, 2724 Skipped, 26h 46m 14.01s Total Time

datadog-ddstaging[bot] avatar Sep 26 '24 16: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 (6089) - mean (71ms)  : 67, 75
     .   : milestone, 71,
    master - mean (70ms)  : 68, 72
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (6089) - mean (1,110ms)  : 1085, 1135
     .   : milestone, 1110,
    master - mean (1,101ms)  : 1079, 1124
     .   : milestone, 1101,


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

    section CallTarget+Inlining+NGEN
    This PR (6089) - mean (777ms)  : 755, 799
     .   : milestone, 777,
    master - mean (769ms)  : 748, 790
     .   : milestone, 769,


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

    section CallTarget+Inlining+NGEN
    This PR (6089) - mean (733ms)  : 714, 753
     .   : milestone, 733,
    master - mean (731ms)  : 714, 747
     .   : milestone, 731,


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

    section CallTarget+Inlining+NGEN
    This PR (6089) - mean (1,199ms)  : 1176, 1223
     .   : milestone, 1199,
    master - mean (1,199ms)  : 1174, 1223
     .   : milestone, 1199,


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

    section CallTarget+Inlining+NGEN
    This PR (6089) - mean (941ms)  : 926, 956
     .   : milestone, 941,
    master - mean (939ms)  : 918, 961
     .   : milestone, 939,


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

    section CallTarget+Inlining+NGEN
    This PR (6089) - mean (926ms)  : 911, 941
     .   : milestone, 926,
    master - mean (923ms)  : 901, 945
     .   : milestone, 923,

andrewlock avatar Sep 26 '24 16:09 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #6089 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.130
  • 2 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.78μs 43.8ns 297ns 0.0197 0.0118 0.00394 5.42 KB
master StartStopWithChild netcoreapp3.1 10.2μs 56.3ns 328ns 0.0195 0.00975 0 5.61 KB
master StartStopWithChild net472 16.1μs 47.4ns 183ns 0.997 0.278 0.0817 6.06 KB
#6089 StartStopWithChild net6.0 7.9μs 45.7ns 369ns 0.0146 0.00731 0 5.43 KB
#6089 StartStopWithChild netcoreapp3.1 9.67μs 49.7ns 253ns 0.0185 0.00463 0 5.62 KB
#6089 StartStopWithChild net472 16.1μs 56.7ns 220ns 1.01 0.295 0.0958 6.07 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 465μs 325ns 1.26μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 653μs 274ns 1.06μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 832μs 492ns 1.91μs 0.417 0 0 3.3 KB
#6089 WriteAndFlushEnrichedTraces net6.0 493μs 542ns 2.1μs 0 0 0 2.7 KB
#6089 WriteAndFlushEnrichedTraces netcoreapp3.1 641μs 511ns 1.91μs 0 0 0 2.7 KB
#6089 WriteAndFlushEnrichedTraces net472 825μs 346ns 1.34μs 0.408 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 6.04μs 0.194 0 0 18.45 KB
master SendRequest netcoreapp3.1 218μs 1.24μs 9.51μs 0.209 0 0 20.61 KB
master SendRequest net472 0.000432ns 0.000274ns 0.00102ns 0 0 0 0 b
#6089 SendRequest net6.0 192μs 1.08μs 7.39μs 0.214 0 0 18.45 KB
#6089 SendRequest netcoreapp3.1 218μs 1.26μs 10.2μs 0.226 0 0 20.61 KB
#6089 SendRequest net472 0.000301ns 0.000295ns 0.0011ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed :heavy_check_mark: Fewer allocations :tada:

Fewer allocations :tada: in #6089

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑net6.0 41.81 KB 41.56 KB -249 B -0.60%
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1 41.95 KB 41.66 KB -289 B -0.69%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 591μs 3.02μs 13.5μs 0.563 0 0 41.81 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 696μs 2.95μs 12.5μs 0.343 0 0 41.95 KB
master WriteAndFlushEnrichedTraces net472 848μs 2.76μs 9.96μs 8.08 2.55 0.425 53.28 KB
#6089 WriteAndFlushEnrichedTraces net6.0 557μs 1.4μs 5.06μs 0.561 0 0 41.56 KB
#6089 WriteAndFlushEnrichedTraces netcoreapp3.1 669μs 2.58μs 9.67μs 0.327 0 0 41.66 KB
#6089 WriteAndFlushEnrichedTraces net472 856μs 3.43μs 13.3μs 8.75 2.5 0.417 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.29μs 1.12ns 4.35ns 0.0142 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.79μs 1.08ns 4.17ns 0.0135 0 0 1.02 KB
master ExecuteNonQuery net472 2.06μs 1.75ns 6.79ns 0.157 0 0 987 B
#6089 ExecuteNonQuery net6.0 1.33μs 0.601ns 2.17ns 0.0146 0 0 1.02 KB
#6089 ExecuteNonQuery netcoreapp3.1 1.73μs 0.855ns 3.08ns 0.0138 0 0 1.02 KB
#6089 ExecuteNonQuery net472 2.03μs 2.01ns 7.79ns 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.24μs 1.12ns 4.33ns 0.0137 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.47μs 0.756ns 2.83ns 0.0132 0 0 976 B
master CallElasticsearch net472 2.53μs 2.08ns 8.06ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.3μs 0.646ns 2.5ns 0.0131 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.68μs 0.758ns 2.94ns 0.0135 0 0 1.02 KB
master CallElasticsearchAsync net472 2.65μs 1.62ns 6.29ns 0.166 0 0 1.05 KB
#6089 CallElasticsearch net6.0 1.21μs 0.324ns 1.21ns 0.014 0 0 976 B
#6089 CallElasticsearch netcoreapp3.1 1.56μs 0.94ns 3.64ns 0.0132 0 0 976 B
#6089 CallElasticsearch net472 2.49μs 1.17ns 4.54ns 0.157 0 0 995 B
#6089 CallElasticsearchAsync net6.0 1.21μs 1.28ns 4.96ns 0.0133 0 0 952 B
#6089 CallElasticsearchAsync netcoreapp3.1 1.62μs 0.603ns 2.17ns 0.0136 0 0 1.02 KB
#6089 CallElasticsearchAsync net472 2.7μs 1.2ns 4.48ns 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.643ns 2.32ns 0.0133 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.62μs 1.64ns 6.34ns 0.0123 0 0 952 B
master ExecuteAsync net472 1.77μs 2.82ns 10.9ns 0.145 0 0 915 B
#6089 ExecuteAsync net6.0 1.18μs 0.502ns 1.88ns 0.0135 0 0 952 B
#6089 ExecuteAsync netcoreapp3.1 1.59μs 0.713ns 2.67ns 0.0126 0 0 952 B
#6089 ExecuteAsync net472 1.82μs 0.506ns 1.96ns 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.26μs 3.39ns 13.1ns 0.0297 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.14μs 5.22ns 20.2ns 0.0382 0 0 2.76 KB
master SendAsync net472 7.8μs 16.4ns 63.5ns 0.497 0 0 3.15 KB
#6089 SendAsync net6.0 4.15μs 1.37ns 5.12ns 0.0311 0 0 2.22 KB
#6089 SendAsync netcoreapp3.1 5.09μs 2.66ns 10.3ns 0.0357 0 0 2.76 KB
#6089 SendAsync net472 7.83μs 14.3ns 55.2ns 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.43μs 0.62ns 2.32ns 0.0228 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.24μs 0.947ns 3.67ns 0.0224 0 0 1.64 KB
master EnrichedLog net472 2.5μs 1.36ns 5.28ns 0.249 0 0 1.57 KB
#6089 EnrichedLog net6.0 1.49μs 0.614ns 2.3ns 0.0232 0 0 1.64 KB
#6089 EnrichedLog netcoreapp3.1 2.25μs 0.406ns 1.41ns 0.0224 0 0 1.64 KB
#6089 EnrichedLog net472 2.54μs 2.22ns 8.6ns 0.25 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 114ns 440ns 0.0571 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 118μs 164ns 634ns 0 0 0 4.28 KB
master EnrichedLog net472 148μs 195ns 756ns 0.661 0.22 0 4.46 KB
#6089 EnrichedLog net6.0 116μs 142ns 549ns 0.0582 0 0 4.28 KB
#6089 EnrichedLog netcoreapp3.1 121μs 218ns 842ns 0 0 0 4.28 KB
#6089 EnrichedLog net472 147μs 118ns 459ns 0.665 0.222 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μs 2.57ns 9.95ns 0.0315 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.05μs 4.61ns 17.9ns 0.0284 0 0 2.2 KB
master EnrichedLog net472 4.83μs 1.97ns 7.36ns 0.319 0 0 2.02 KB
#6089 EnrichedLog net6.0 3.18μs 1.13ns 4.4ns 0.0302 0 0 2.2 KB
#6089 EnrichedLog netcoreapp3.1 4.18μs 1ns 3.76ns 0.0292 0 0 2.2 KB
#6089 EnrichedLog net472 4.86μs 0.863ns 3.23ns 0.319 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.4μs 0.634ns 2.46ns 0.0161 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.81μs 0.487ns 1.76ns 0.0153 0 0 1.14 KB
master SendReceive net472 2.12μs 1.32ns 4.94ns 0.184 0 0 1.16 KB
#6089 SendReceive net6.0 1.26μs 0.61ns 2.36ns 0.0157 0 0 1.14 KB
#6089 SendReceive netcoreapp3.1 1.8μs 0.556ns 2ns 0.0153 0 0 1.14 KB
#6089 SendReceive net472 2.17μs 1.44ns 5.18ns 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.83μs 0.458ns 1.65ns 0.0227 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.94μs 10.5ns 40.7ns 0.0215 0 0 1.65 KB
master EnrichedLog net472 4.31μs 2.02ns 7.56ns 0.323 0 0 2.04 KB
#6089 EnrichedLog net6.0 2.64μs 0.832ns 3.22ns 0.0226 0 0 1.6 KB
#6089 EnrichedLog netcoreapp3.1 3.92μs 1.07ns 4.15ns 0.0216 0 0 1.65 KB
#6089 EnrichedLog net472 4.34μs 1.48ns 5.74ns 0.322 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6089

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.128 448.21 397.34

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 449ns 0.601ns 2.33ns 0.00809 0 0 576 B
master StartFinishSpan netcoreapp3.1 657ns 1.59ns 6.17ns 0.00778 0 0 576 B
master StartFinishSpan net472 677ns 0.516ns 2ns 0.0917 0 0 578 B
master StartFinishScope net6.0 498ns 0.417ns 1.61ns 0.0097 0 0 696 B
master StartFinishScope netcoreapp3.1 790ns 0.322ns 1.25ns 0.00917 0 0 696 B
master StartFinishScope net472 821ns 3.73ns 14.4ns 0.104 0 0 658 B
#6089 StartFinishSpan net6.0 397ns 0.255ns 0.987ns 0.00819 0 0 576 B
#6089 StartFinishSpan netcoreapp3.1 636ns 0.468ns 1.81ns 0.0079 0 0 576 B
#6089 StartFinishSpan net472 751ns 0.682ns 2.46ns 0.0917 0 0 578 B
#6089 StartFinishScope net6.0 484ns 0.388ns 1.5ns 0.00979 0 0 696 B
#6089 StartFinishScope netcoreapp3.1 717ns 0.375ns 1.4ns 0.00935 0 0 696 B
#6089 StartFinishScope net472 839ns 1.46ns 5.65ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6089

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 1.131 743.56 657.26

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 744ns 0.548ns 2.12ns 0.00969 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 905ns 1.63ns 6.3ns 0.00941 0 0 696 B
master RunOnMethodBegin net472 1.14μs 0.987ns 3.82ns 0.104 0 0 658 B
#6089 RunOnMethodBegin net6.0 657ns 0.39ns 1.51ns 0.00982 0 0 696 B
#6089 RunOnMethodBegin netcoreapp3.1 915ns 0.423ns 1.64ns 0.00916 0 0 696 B
#6089 RunOnMethodBegin net472 1.16μs 0.884ns 3.42ns 0.104 0 0 658 B

andrewlock avatar Sep 26 '24 17: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 (6089) (10.981M)   : 0, 10981252
    master (11.005M)   : 0, 11004997
    benchmarks/2.9.0 (11.081M)   : 0, 11080577

    section Automatic
    This PR (6089) (7.264M)   : 0, 7263926
    master (7.294M)   : 0, 7294497
    benchmarks/2.9.0 (7.732M)   : 0, 7732233

    section Trace stats
    master (7.666M)   : 0, 7665717

    section Manual
    master (10.962M)   : 0, 10962266

    section Manual + Automatic
    This PR (6089) (6.809M)   : 0, 6808988
    master (6.871M)   : 0, 6871359

    section DD_TRACE_ENABLED=0
    master (10.088M)   : 0, 10087520


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6089) (9.450M)   : 0, 9449836
    master (9.417M)   : 0, 9417337
    benchmarks/2.9.0 (9.798M)   : 0, 9798067

    section Automatic
    This PR (6089) (6.411M)   : 0, 6411078
    master (6.457M)   : 0, 6456701

    section Trace stats
    master (6.829M)   : 0, 6829360

    section Manual
    master (9.508M)   : 0, 9508295

    section Manual + Automatic
    This PR (6089) (6.083M)   : 0, 6082687
    master (6.099M)   : 0, 6099250

    section DD_TRACE_ENABLED=0
    master (8.869M)   : 0, 8869399


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6089) (10.349M)   : 0, 10349282
    master (10.122M)   : 0, 10121837
    benchmarks/2.9.0 (10.067M)   : 0, 10067315

    section Automatic
    This PR (6089) (6.916M)   : 0, 6916420
    master (6.643M)   : 0, 6642678
    benchmarks/2.9.0 (7.552M)   : 0, 7552193

    section Trace stats
    master (7.299M)   : 0, 7299179

    section Manual
    master (10.010M)   : 0, 10009742

    section Manual + Automatic
    This PR (6089) (6.440M)   : 0, 6439668
    master (6.176M)   : 0, 6176268

    section DD_TRACE_ENABLED=0
    master (9.288M)   : 0, 9287893

andrewlock avatar Sep 26 '24 21:09 andrewlock

I'm not quite sure why, but this seems to have broken all the exploration tests, seemingly in the variable generation step 🤔

All investigation tests are now passed, I would appreciate your review.

dudikeleti avatar Oct 01 '24 12:10 dudikeleti