Skip to content

[Profiler] Support Single Step Instrumentation deployment and activation#5240

Merged
chrisnas merged 85 commits into
masterfrom
chrisnas/support_ssi_telemetry
Sep 4, 2024
Merged

[Profiler] Support Single Step Instrumentation deployment and activation#5240
chrisnas merged 85 commits into
masterfrom
chrisnas/support_ssi_telemetry

Conversation

@chrisnas

@chrisnas chrisnas commented Feb 26, 2024

Copy link
Copy Markdown
Contributor

Summary of changes

Add IProfilerTelemetry definition and implementation to be able to send metrics related to SSI deployment
and impacts on the generated or not profiles based on heuristics (first span created and process lifetime > 30 seconds).
The profiler is now able to start with a delay based on the heuristics.

Reason for change

Get statistics about heuristics effects when deployed with SSI and support delayed start of the profiler based on heuristics.

Implementation details

Major refactoring to allow delay start of the profiler.

Test coverage

Corresponding tests have been added both for the configuration and the runtime behavior depending on new "auto" value and "profiler" in env vars.

Other details

@chrisnas
chrisnas requested a review from a team as a code owner February 26, 2024 18:29
@github-actions github-actions Bot added the area:profiler Issues related to the continous-profiler label Feb 26, 2024
@andrewlock

andrewlock commented Feb 26, 2024

Copy link
Copy Markdown
Member

Execution-Time Benchmarks Report ⏱️

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 (5240) - mean (71ms)  : 68, 75
     .   : milestone, 71,
    master - mean (70ms)  : 66, 73
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (5240) - mean (1,082ms)  : 1055, 1109
     .   : milestone, 1082,
    master - mean (1,073ms)  : 1048, 1097
     .   : milestone, 1073,

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

    section CallTarget+Inlining+NGEN
    This PR (5240) - mean (759ms)  : 741, 776
     .   : milestone, 759,
    master - mean (753ms)  : 728, 777
     .   : milestone, 753,

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

    section CallTarget+Inlining+NGEN
    This PR (5240) - mean (708ms)  : 689, 727
     .   : milestone, 708,
    master - mean (701ms)  : 684, 718
     .   : milestone, 701,

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

    section CallTarget+Inlining+NGEN
    This PR (5240) - mean (1,161ms)  : 1136, 1187
     .   : milestone, 1161,
    master - mean (1,158ms)  : 1137, 1178
     .   : milestone, 1158,

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

    section CallTarget+Inlining+NGEN
    This PR (5240) - mean (922ms)  : 901, 942
     .   : milestone, 922,
    master - mean (919ms)  : 903, 936
     .   : milestone, 919,

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

    section CallTarget+Inlining+NGEN
    This PR (5240) - mean (910ms)  : 888, 932
     .   : milestone, 910,
    master - mean (904ms)  : 875, 932
     .   : milestone, 904,

Loading

@datadog-ddstaging

datadog-ddstaging Bot commented Feb 26, 2024

Copy link
Copy Markdown

Datadog Report

Branch report: chrisnas/support_ssi_telemetry
Commit report: 08f4345
Test service: dd-trace-dotnet

✅ 0 Failed, 336167 Passed, 1888 Skipped, 43m 34.01s Wall Time

@andrewlock

andrewlock commented Feb 26, 2024

Copy link
Copy Markdown
Member

Benchmarks Report 🐌

Benchmarks for #5240 compared to master:

  • 3 benchmarks are faster, with geometric mean 1.262
  • 1 benchmarks are slower, with geometric mean 1.157
  • 1 benchmarks have fewer allocations
  • 3 benchmarks have more 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 ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartStopWithChild net6.0 8.83μs 46.6ns 223ns 0.0215 0.00859 0 7.5 KB
master StartStopWithChild netcoreapp3.1 10.5μs 56.7ns 300ns 0.0258 0.0103 0 7.58 KB
master StartStopWithChild net472 16.9μs 81.7ns 316ns 1.35 0.363 0.132 7.95 KB
#5240 StartStopWithChild net6.0 8.7μs 48.5ns 295ns 0.0306 0.0131 0 7.48 KB
#5240 StartStopWithChild netcoreapp3.1 10.8μs 58.9ns 358ns 0.0312 0.0156 0 7.59 KB
#5240 StartStopWithChild net472 17μs 65.2ns 252ns 1.33 0.363 0.101 7.96 KB
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 457μs 491ns 1.9μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 624μs 198ns 766ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 818μs 390ns 1.51μs 0.411 0 0 3.3 KB
#5240 WriteAndFlushEnrichedTraces net6.0 488μs 173ns 623ns 0 0 0 2.7 KB
#5240 WriteAndFlushEnrichedTraces netcoreapp3.1 611μs 244ns 913ns 0 0 0 2.7 KB
#5240 WriteAndFlushEnrichedTraces net472 810μs 399ns 1.49μs 0.403 0 0 3.3 KB
Benchmarks.Trace.Asm.AppSecBodyBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #5240

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑net472 1.157 171.88 198.92

Faster 🎉 in #5240

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑netcoreapp3.1 1.216 245.33 201.80

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master AllCycleSimpleBody net6.0 40.4μs 16.9ns 61ns 0.0202 0 0 2.36 KB
master AllCycleSimpleBody netcoreapp3.1 43.7μs 22ns 79.3ns 0.0219 0 0 2.34 KB
master AllCycleSimpleBody net472 47μs 13.4ns 50.1ns 0.375 0 0 2.41 KB
master AllCycleMoreComplexBody net6.0 213μs 89.6ns 347ns 0.106 0 0 9.84 KB
master AllCycleMoreComplexBody netcoreapp3.1 224μs 183ns 686ns 0.112 0 0 9.73 KB
master AllCycleMoreComplexBody net472 240μs 90.4ns 350ns 1.56 0 0 9.91 KB
master ObjectExtractorSimpleBody net6.0 141ns 0.058ns 0.209ns 0.00395 0 0 280 B
master ObjectExtractorSimpleBody netcoreapp3.1 245ns 0.1ns 0.376ns 0.00369 0 0 272 B
master ObjectExtractorSimpleBody net472 172ns 0.111ns 0.428ns 0.0446 0 0 281 B
master ObjectExtractorMoreComplexBody net6.0 3.04μs 1.67ns 6.23ns 0.0532 0 0 3.78 KB
master ObjectExtractorMoreComplexBody netcoreapp3.1 4.03μs 1.75ns 6.55ns 0.0503 0 0 3.69 KB
master ObjectExtractorMoreComplexBody net472 4.44μs 2.23ns 8.62ns 0.603 0.00665 0 3.8 KB
#5240 AllCycleSimpleBody net6.0 41.7μs 76.2ns 295ns 0.021 0 0 2.36 KB
#5240 AllCycleSimpleBody netcoreapp3.1 44.6μs 80ns 310ns 0.0222 0 0 2.34 KB
#5240 AllCycleSimpleBody net472 47.3μs 62.7ns 243ns 0.373 0 0 2.41 KB
#5240 AllCycleMoreComplexBody net6.0 215μs 48.5ns 181ns 0.108 0 0 9.84 KB
#5240 AllCycleMoreComplexBody netcoreapp3.1 226μs 193ns 748ns 0.113 0 0 9.73 KB
#5240 AllCycleMoreComplexBody net472 240μs 83.1ns 311ns 1.56 0 0 9.91 KB
#5240 ObjectExtractorSimpleBody net6.0 139ns 0.132ns 0.51ns 0.00395 0 0 280 B
#5240 ObjectExtractorSimpleBody netcoreapp3.1 202ns 0.109ns 0.424ns 0.00365 0 0 272 B
#5240 ObjectExtractorSimpleBody net472 199ns 0.0898ns 0.336ns 0.0446 0 0 281 B
#5240 ObjectExtractorMoreComplexBody net6.0 2.96μs 1.11ns 4.15ns 0.0531 0 0 3.78 KB
#5240 ObjectExtractorMoreComplexBody netcoreapp3.1 3.98μs 2.08ns 7.51ns 0.0498 0 0 3.69 KB
#5240 ObjectExtractorMoreComplexBody net472 4.23μs 3ns 11.6ns 0.602 0.00634 0 3.8 KB
Benchmarks.Trace.Asm.AppSecEncoderBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EncodeArgs net6.0 53.5μs 74.6ns 289ns 0.429 0 0 30.94 KB
master EncodeArgs netcoreapp3.1 70.9μs 58.6ns 219ns 0.425 0 0 31.47 KB
master EncodeArgs net472 84.8μs 38.2ns 138ns 5.12 0.086 0 32.27 KB
master EncodeLegacyArgs net6.0 128μs 154ns 578ns 0.444 0 0 33.89 KB
master EncodeLegacyArgs netcoreapp3.1 155μs 157ns 608ns 0.453 0 0 34.09 KB
master EncodeLegacyArgs net472 214μs 557ns 2.16μs 5.47 0.429 0 34.99 KB
#5240 EncodeArgs net6.0 51.8μs 61ns 228ns 0.415 0 0 30.94 KB
#5240 EncodeArgs netcoreapp3.1 70.2μs 134ns 518ns 0.415 0 0 31.47 KB
#5240 EncodeArgs net472 84.7μs 98.3ns 381ns 5.1 0.0842 0 32.27 KB
#5240 EncodeLegacyArgs net6.0 127μs 595ns 2.31μs 0.424 0 0 33.89 KB
#5240 EncodeLegacyArgs netcoreapp3.1 156μs 425ns 1.65μs 0.466 0 0 34.09 KB
#5240 EncodeLegacyArgs net472 211μs 164ns 592ns 5.51 0.424 0 34.99 KB
Benchmarks.Trace.Asm.AppSecWafBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunWafRealisticBenchmark net6.0 190μs 526ns 2.04μs 0.0953 0 0 6.51 KB
master RunWafRealisticBenchmark netcoreapp3.1 207μs 446ns 1.73μs 0 0 0 6.49 KB
master RunWafRealisticBenchmark net472 224μs 113ns 438ns 1.01 0 0 6.59 KB
master RunWafRealisticBenchmarkWithAttack net6.0 125μs 81.6ns 294ns 0.0627 0 0 4.15 KB
master RunWafRealisticBenchmarkWithAttack netcoreapp3.1 135μs 216ns 835ns 0 0 0 4.15 KB
master RunWafRealisticBenchmarkWithAttack net472 147μs 163ns 630ns 0.66 0 0 4.19 KB
#5240 RunWafRealisticBenchmark net6.0 191μs 158ns 612ns 0.0962 0 0 6.51 KB
#5240 RunWafRealisticBenchmark netcoreapp3.1 206μs 302ns 1.17μs 0 0 0 6.49 KB
#5240 RunWafRealisticBenchmark net472 225μs 98.1ns 380ns 1.01 0 0 6.59 KB
#5240 RunWafRealisticBenchmarkWithAttack net6.0 127μs 157ns 566ns 0.0628 0 0 4.15 KB
#5240 RunWafRealisticBenchmarkWithAttack netcoreapp3.1 139μs 240ns 929ns 0 0 0 4.15 KB
#5240 RunWafRealisticBenchmarkWithAttack net472 148μs 64.5ns 250ns 0.663 0 0 4.19 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 175μs 205ns 794ns 0.174 0 0 18.26 KB
master SendRequest netcoreapp3.1 195μs 271ns 1.05μs 0.195 0 0 20.42 KB
master SendRequest net472 0.000804ns 0.000236ns 0.000883ns 0 0 0 0 b
#5240 SendRequest net6.0 172μs 150ns 563ns 0.171 0 0 18.26 KB
#5240 SendRequest netcoreapp3.1 194μs 197ns 763ns 0.193 0 0 20.42 KB
#5240 SendRequest net472 2.09E‑05ns 2.09E‑05ns 7.55E‑05ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 553μs 801ns 3.1μs 0.551 0 0 41.69 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 646μs 320ns 1.11μs 0.326 0 0 41.67 KB
master WriteAndFlushEnrichedTraces net472 838μs 2.08μs 8.07μs 8.45 2.53 0.422 53.24 KB
#5240 WriteAndFlushEnrichedTraces net6.0 537μs 577ns 2.24μs 0.539 0 0 41.76 KB
#5240 WriteAndFlushEnrichedTraces netcoreapp3.1 655μs 1.35μs 5.22μs 0.332 0 0 41.79 KB
#5240 WriteAndFlushEnrichedTraces net472 836μs 2.03μs 7.86μs 8.08 2.55 0.425 53.26 KB
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.12μs 0.385ns 1.39ns 0.0112 0 0 776 B
master ExecuteNonQuery netcoreapp3.1 1.5μs 1.75ns 6.79ns 0.00992 0 0 776 B
master ExecuteNonQuery net472 1.75μs 0.917ns 3.18ns 0.117 0 0 738 B
#5240 ExecuteNonQuery net6.0 1.22μs 0.569ns 2.13ns 0.011 0 0 776 B
#5240 ExecuteNonQuery netcoreapp3.1 1.48μs 0.536ns 2.01ns 0.0103 0 0 776 B
#5240 ExecuteNonQuery net472 1.78μs 1.62ns 6.07ns 0.117 0 0 738 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.18μs 0.597ns 2.31ns 0.0131 0 0 944 B
master CallElasticsearch netcoreapp3.1 1.54μs 1.12ns 4.18ns 0.0124 0 0 944 B
master CallElasticsearch net472 2.51μs 0.926ns 3.59ns 0.153 0 0 963 B
master CallElasticsearchAsync net6.0 1.3μs 0.595ns 2.23ns 0.013 0 0 920 B
master CallElasticsearchAsync netcoreapp3.1 1.64μs 1.33ns 5.15ns 0.0133 0 0 992 B
master CallElasticsearchAsync net472 2.63μs 0.924ns 3.58ns 0.162 0 0 1.02 KB
#5240 CallElasticsearch net6.0 1.18μs 0.523ns 2.03ns 0.0129 0 0 944 B
#5240 CallElasticsearch netcoreapp3.1 1.5μs 0.518ns 1.94ns 0.0131 0 0 944 B
#5240 CallElasticsearch net472 2.48μs 0.446ns 1.61ns 0.153 0 0 963 B
#5240 CallElasticsearchAsync net6.0 1.26μs 0.483ns 1.74ns 0.0126 0 0 920 B
#5240 CallElasticsearchAsync netcoreapp3.1 1.67μs 0.506ns 1.89ns 0.0135 0 0 992 B
#5240 CallElasticsearchAsync net472 2.7μs 1.73ns 6.24ns 0.161 0 0 1.02 KB
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.19μs 1.41ns 5.45ns 0.0132 0 0 920 B
master ExecuteAsync netcoreapp3.1 1.63μs 0.968ns 3.75ns 0.0123 0 0 920 B
master ExecuteAsync net472 1.82μs 0.915ns 3.54ns 0.14 0 0 883 B
#5240 ExecuteAsync net6.0 1.25μs 0.391ns 1.51ns 0.0125 0 0 920 B
#5240 ExecuteAsync netcoreapp3.1 1.61μs 1.09ns 4.08ns 0.012 0 0 920 B
#5240 ExecuteAsync net472 1.8μs 0.856ns 3.32ns 0.14 0 0 883 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net6.0 4.03μs 1.83ns 6.85ns 0.0282 0 0 2.1 KB
master SendAsync netcoreapp3.1 5.04μs 2.56ns 9.57ns 0.0355 0 0 2.64 KB
master SendAsync net472 7.81μs 1.92ns 7.42ns 0.524 0 0 3.31 KB
#5240 SendAsync net6.0 4μs 2.37ns 8.87ns 0.0299 0 0 2.1 KB
#5240 SendAsync netcoreapp3.1 4.81μs 2.01ns 7.52ns 0.0363 0 0 2.64 KB
#5240 SendAsync net472 7.73μs 2.64ns 10.2ns 0.525 0 0 3.31 KB
Benchmarks.Trace.Iast.StringAspectsBenchmark - Same speed ✔️ More allocations ⚠️

More allocations ⚠️ in #5240

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑netcoreapp3.1 202.26 KB 205.27 KB 3.02 KB 1.49%
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark‑net472 60.95 KB 61.83 KB 880 B 1.44%
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑net6.0 203.6 KB 204.9 KB 1.3 KB 0.64%

Fewer allocations 🎉 in #5240

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑net472 229.38 KB 221.18 KB -8.19 KB -3.57%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StringConcatBenchmark net6.0 61.3μs 1.04μs 10.2μs 0 0 0 43.44 KB
master StringConcatBenchmark netcoreapp3.1 53.1μs 258ns 1.06μs 0 0 0 42.64 KB
master StringConcatBenchmark net472 37.9μs 93.5ns 350ns 0 0 0 60.95 KB
master StringConcatAspectBenchmark net6.0 279μs 1.02μs 3.52μs 0 0 0 203.6 KB
master StringConcatAspectBenchmark netcoreapp3.1 282μs 1.51μs 8.92μs 0 0 0 202.26 KB
master StringConcatAspectBenchmark net472 226μs 1.2μs 6.48μs 0 0 0 229.38 KB
#5240 StringConcatBenchmark net6.0 57.5μs 567ns 5.52μs 0 0 0 43.44 KB
#5240 StringConcatBenchmark netcoreapp3.1 56.8μs 546ns 5.32μs 0 0 0 42.64 KB
#5240 StringConcatBenchmark net472 36.8μs 44.9ns 156ns 0 0 0 61.83 KB
#5240 StringConcatAspectBenchmark net6.0 271μs 1.2μs 6.11μs 0 0 0 204.9 KB
#5240 StringConcatAspectBenchmark netcoreapp3.1 306μs 1.72μs 11.9μs 0 0 0 205.27 KB
#5240 StringConcatAspectBenchmark net472 239μs 2.49μs 23.5μs 0 0 0 221.18 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 1.42μs 0.666ns 2.49ns 0.022 0 0 1.58 KB
master EnrichedLog netcoreapp3.1 2.26μs 0.925ns 3.58ns 0.0217 0 0 1.58 KB
master EnrichedLog net472 2.59μs 3.23ns 12.5ns 0.239 0 0 1.51 KB
#5240 EnrichedLog net6.0 1.54μs 0.99ns 3.83ns 0.0218 0 0 1.58 KB
#5240 EnrichedLog netcoreapp3.1 2.24μs 0.842ns 3.15ns 0.0214 0 0 1.58 KB
#5240 EnrichedLog net472 2.46μs 1.42ns 5.31ns 0.239 0 0 1.51 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 113μs 117ns 454ns 0.0566 0 0 4.22 KB
master EnrichedLog netcoreapp3.1 119μs 204ns 790ns 0 0 0 4.22 KB
master EnrichedLog net472 148μs 212ns 822ns 0.67 0.223 0 4.4 KB
#5240 EnrichedLog net6.0 113μs 69.1ns 268ns 0.0562 0 0 4.22 KB
#5240 EnrichedLog netcoreapp3.1 120μs 193ns 721ns 0 0 0 4.22 KB
#5240 EnrichedLog net472 148μs 100ns 388ns 0.665 0.222 0 4.4 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 3.01μs 1.82ns 6.82ns 0.0301 0 0 2.14 KB
master EnrichedLog netcoreapp3.1 4.15μs 1.39ns 5.2ns 0.0291 0 0 2.14 KB
master EnrichedLog net472 4.84μs 2.06ns 7.99ns 0.309 0 0 1.95 KB
#5240 EnrichedLog net6.0 3.08μs 0.99ns 3.84ns 0.0296 0 0 2.14 KB
#5240 EnrichedLog netcoreapp3.1 4.32μs 3.13ns 11.3ns 0.0285 0 0 2.14 KB
#5240 EnrichedLog net472 4.8μs 0.957ns 3.58ns 0.31 0 0 1.95 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net6.0 1.4μs 0.516ns 2ns 0.0155 0 0 1.11 KB
master SendReceive netcoreapp3.1 1.77μs 0.867ns 3.36ns 0.015 0 0 1.11 KB
master SendReceive net472 2.11μs 1.3ns 4.88ns 0.178 0 0 1.12 KB
#5240 SendReceive net6.0 1.33μs 0.631ns 2.45ns 0.0153 0 0 1.11 KB
#5240 SendReceive netcoreapp3.1 1.7μs 3.39ns 13.1ns 0.0152 0 0 1.11 KB
#5240 SendReceive net472 2.12μs 1.67ns 6.48ns 0.178 0 0 1.12 KB
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.78μs 1.1ns 4.27ns 0.0222 0 0 1.54 KB
master EnrichedLog netcoreapp3.1 3.86μs 2.82ns 10.9ns 0.0212 0 0 1.58 KB
master EnrichedLog net472 4.3μs 1.84ns 7.14ns 0.313 0 0 1.97 KB
#5240 EnrichedLog net6.0 2.71μs 0.869ns 3.25ns 0.0217 0 0 1.54 KB
#5240 EnrichedLog netcoreapp3.1 3.98μs 2.55ns 9.89ns 0.0218 0 0 1.58 KB
#5240 EnrichedLog net472 4.19μs 2.01ns 7.78ns 0.313 0 0 1.97 KB
Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #5240

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 1.303 833.44 639.68
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.268 584.86 461.19

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 585ns 0.524ns 2.03ns 0.00773 0 0 544 B
master StartFinishSpan netcoreapp3.1 833ns 1.81ns 7ns 0.00704 0 0 544 B
master StartFinishSpan net472 755ns 1.83ns 7.08ns 0.0864 0 0 546 B
master StartFinishScope net6.0 652ns 0.822ns 3.18ns 0.00946 0 0 664 B
master StartFinishScope netcoreapp3.1 780ns 1.61ns 6.25ns 0.00893 0 0 664 B
master StartFinishScope net472 984ns 2.35ns 9.08ns 0.0993 0 0 626 B
#5240 StartFinishSpan net6.0 459ns 1.26ns 4.88ns 0.00763 0 0 544 B
#5240 StartFinishSpan netcoreapp3.1 639ns 0.96ns 3.72ns 0.00745 0 0 544 B
#5240 StartFinishSpan net472 721ns 1.22ns 4.72ns 0.0867 0 0 546 B
#5240 StartFinishScope net6.0 650ns 0.816ns 2.94ns 0.00946 0 0 664 B
#5240 StartFinishScope netcoreapp3.1 838ns 2.88ns 11.2ns 0.00917 0 0 664 B
#5240 StartFinishScope net472 953ns 1.66ns 6.45ns 0.0994 0 0 626 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 589ns 1.01ns 3.9ns 0.00924 0 0 664 B
master RunOnMethodBegin netcoreapp3.1 1E+03ns 1.69ns 6.55ns 0.00896 0 0 664 B
master RunOnMethodBegin net472 1.09μs 2.02ns 7.83ns 0.0993 0 0 626 B
#5240 RunOnMethodBegin net6.0 601ns 1.02ns 3.97ns 0.00928 0 0 664 B
#5240 RunOnMethodBegin netcoreapp3.1 1μs 1.72ns 6.68ns 0.00893 0 0 664 B
#5240 RunOnMethodBegin net472 1.1μs 3.01ns 11.7ns 0.099 0 0 626 B

@andrewlock

andrewlock commented Feb 27, 2024

Copy link
Copy Markdown
Member

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 (5240) (11.808M)   : 0, 11808301
    master (11.782M)   : 0, 11782230
    benchmarks/2.9.0 (12.049M)   : 0, 12048905

    section Automatic
    This PR (5240) (7.906M)   : 0, 7905866
    master (8.000M)   : 0, 7999809
    benchmarks/2.9.0 (8.464M)   : 0, 8463997

    section Trace stats
    master (8.220M)   : 0, 8219910

    section Manual
    This PR (5240) (10.249M)   : 0, 10248571
    master (10.121M)   : 0, 10121081

    section Manual + Automatic
    This PR (5240) (7.548M)   : 0, 7548361
    master (7.401M)   : 0, 7401424

    section Version Conflict
    master (6.682M)   : 0, 6682420

Loading
gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5240) (9.686M)   : 0, 9686363
    master (9.468M)   : 0, 9468472
    benchmarks/2.9.0 (9.590M)   : 0, 9590349

    section Automatic
    This PR (5240) (6.523M)   : 0, 6523266
    master (6.659M)   : 0, 6658834

    section Trace stats
    master (6.910M)   : 0, 6910180

    section Manual
    This PR (5240) (8.138M)   : 0, 8137641
    master (8.171M)   : 0, 8171310

    section Manual + Automatic
    This PR (5240) (6.195M)   : 0, 6194599
    master (6.156M)   : 0, 6155830

    section Version Conflict
    master (5.676M)   : 0, 5675747

Loading
gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5240) (9.985M)   : 0, 9985256
    master (10.079M)   : 0, 10078999
    benchmarks/2.9.0 (10.465M)   : 0, 10465033

    section Automatic
    This PR (5240) (7.033M)   : 0, 7032997
    master (7.135M)   : 0, 7134788
    benchmarks/2.9.0 (7.635M)   : 0, 7635248

    section Trace stats
    master (7.452M)   : 0, 7451968

    section Manual
    This PR (5240) (8.794M)   : 0, 8794420
    master (8.834M)   : 0, 8833858

    section Manual + Automatic
    This PR (5240) (6.827M)   : 0, 6827429
    master (6.875M)   : 0, 6874694

    section Version Conflict
    master (6.177M)   : 0, 6176958

Loading

@andrewlock

andrewlock commented Mar 19, 2024

Copy link
Copy Markdown
Member

Benchmarks Report for tracer 🐌

Benchmarks for #5240 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.192
  • 1 benchmarks have more 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 ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartStopWithChild net6.0 7.82μs 43.5ns 272ns 0.0164 0.00821 0 5.43 KB
master StartStopWithChild netcoreapp3.1 9.88μs 54.1ns 324ns 0.0252 0.0101 0 5.62 KB
master StartStopWithChild net472 16μs 45ns 174ns 1.01 0.31 0.0873 6.06 KB
#5240 StartStopWithChild net6.0 7.6μs 42.5ns 269ns 0.0191 0.00764 0 5.42 KB
#5240 StartStopWithChild netcoreapp3.1 9.87μs 54.2ns 329ns 0.0202 0.0101 0 5.62 KB
#5240 StartStopWithChild net472 15.9μs 61.7ns 239ns 1.02 0.307 0.0946 6.07 KB
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 483μs 1.4μs 5.42μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 632μs 339ns 1.31μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 844μs 548ns 2.12μs 0.417 0 0 3.3 KB
#5240 WriteAndFlushEnrichedTraces net6.0 466μs 365ns 1.41μs 0 0 0 2.7 KB
#5240 WriteAndFlushEnrichedTraces netcoreapp3.1 649μs 2.58μs 9.99μs 0 0 0 2.7 KB
#5240 WriteAndFlushEnrichedTraces net472 835μs 741ns 2.87μs 0.411 0 0 3.3 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 194μs 1.12μs 9.87μs 0.202 0 0 18.45 KB
master SendRequest netcoreapp3.1 209μs 1.11μs 6.49μs 0.202 0 0 20.61 KB
master SendRequest net472 0.00138ns 0.00047ns 0.00169ns 0 0 0 0 b
#5240 SendRequest net6.0 191μs 1.08μs 7.81μs 0.184 0 0 18.45 KB
#5240 SendRequest netcoreapp3.1 219μs 1.24μs 8.75μs 0.211 0 0 20.61 KB
#5240 SendRequest net472 0.000187ns 0.000158ns 0.000613ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ More allocations ⚠️

More allocations ⚠️ in #5240

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑net6.0 41.56 KB 41.85 KB 292 B 0.70%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 543μs 897ns 3.24μs 0.566 0 0 41.56 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 666μs 2.77μs 10.7μs 0.361 0 0 41.66 KB
master WriteAndFlushEnrichedTraces net472 852μs 4.17μs 17.2μs 8.28 2.48 0.414 53.35 KB
#5240 WriteAndFlushEnrichedTraces net6.0 575μs 2.53μs 8.77μs 0.541 0 0 41.85 KB
#5240 WriteAndFlushEnrichedTraces netcoreapp3.1 666μs 2.55μs 9.55μs 0.332 0 0 41.73 KB
#5240 WriteAndFlushEnrichedTraces net472 866μs 4.31μs 17.8μs 8.36 2.64 0.44 53.3 KB
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.27μs 1.48ns 5.74ns 0.014 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.7μs 1.15ns 4.45ns 0.0136 0 0 1.02 KB
master ExecuteNonQuery net472 2.04μs 1.58ns 5.69ns 0.157 0 0 987 B
#5240 ExecuteNonQuery net6.0 1.23μs 1.08ns 4.18ns 0.0142 0 0 1.02 KB
#5240 ExecuteNonQuery netcoreapp3.1 1.74μs 1.16ns 4.34ns 0.014 0 0 1.02 KB
#5240 ExecuteNonQuery net472 1.91μs 2.1ns 7.86ns 0.157 0 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.23μs 0.76ns 2.94ns 0.0135 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.56μs 1.51ns 5.85ns 0.013 0 0 976 B
master CallElasticsearch net472 2.49μs 1.47ns 5.68ns 0.158 0 0 995 B
master CallElasticsearchAsync net6.0 1.29μs 1.68ns 6.3ns 0.0136 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.72μs 0.58ns 2.17ns 0.0137 0 0 1.02 KB
master CallElasticsearchAsync net472 2.63μs 2.24ns 8.69ns 0.167 0 0 1.05 KB
#5240 CallElasticsearch net6.0 1.29μs 1.18ns 4.43ns 0.0134 0 0 976 B
#5240 CallElasticsearch netcoreapp3.1 1.52μs 0.329ns 1.23ns 0.013 0 0 976 B
#5240 CallElasticsearch net472 2.4μs 1.79ns 6.94ns 0.158 0 0 995 B
#5240 CallElasticsearchAsync net6.0 1.4μs 1.12ns 4.34ns 0.0132 0 0 952 B
#5240 CallElasticsearchAsync netcoreapp3.1 1.59μs 4.35ns 16.8ns 0.0134 0 0 1.02 KB
#5240 CallElasticsearchAsync net472 2.58μs 1.8ns 6.98ns 0.167 0 0 1.05 KB
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.24μs 0.926ns 3.47ns 0.0136 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.62μs 1.46ns 5.64ns 0.0129 0 0 952 B
master ExecuteAsync net472 1.76μs 1.08ns 4.05ns 0.145 0 0 915 B
#5240 ExecuteAsync net6.0 1.23μs 0.411ns 1.59ns 0.0129 0 0 952 B
#5240 ExecuteAsync netcoreapp3.1 1.71μs 0.909ns 3.4ns 0.0127 0 0 952 B
#5240 ExecuteAsync net472 1.77μs 0.871ns 3.14ns 0.145 0 0 915 B
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net6.0 4.19μs 0.84ns 3.03ns 0.0314 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.01μs 2.06ns 7.71ns 0.0377 0 0 2.76 KB
master SendAsync net472 7.79μs 1.58ns 6.14ns 0.499 0 0 3.15 KB
#5240 SendAsync net6.0 4.16μs 1.96ns 7.33ns 0.031 0 0 2.22 KB
#5240 SendAsync netcoreapp3.1 4.98μs 1.73ns 6.69ns 0.0374 0 0 2.76 KB
#5240 SendAsync net472 7.91μs 1.62ns 6.04ns 0.499 0 0 3.15 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 1.58μs 0.795ns 3.08ns 0.0229 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.11μs 0.902ns 3.38ns 0.0225 0 0 1.64 KB
master EnrichedLog net472 2.69μs 2.65ns 9.92ns 0.249 0 0 1.57 KB
#5240 EnrichedLog net6.0 1.55μs 0.843ns 3.15ns 0.0226 0 0 1.64 KB
#5240 EnrichedLog netcoreapp3.1 2.16μs 2.65ns 10.3ns 0.0217 0 0 1.64 KB
#5240 EnrichedLog net472 2.62μs 1.69ns 6.32ns 0.249 0 0 1.57 KB
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 116μs 196ns 757ns 0.0572 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 120μs 277ns 1.07μs 0 0 0 4.28 KB
master EnrichedLog net472 150μs 304ns 1.18μs 0.668 0.223 0 4.46 KB
#5240 EnrichedLog net6.0 117μs 246ns 952ns 0.0578 0 0 4.28 KB
#5240 EnrichedLog netcoreapp3.1 118μs 225ns 872ns 0 0 0 4.28 KB
#5240 EnrichedLog net472 149μs 264ns 1.02μs 0.65 0.217 0 4.46 KB
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 3.25μs 1.51ns 5.65ns 0.0308 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.44μs 1.29ns 5ns 0.0281 0 0 2.2 KB
master EnrichedLog net472 4.97μs 1.83ns 7.09ns 0.319 0 0 2.02 KB
#5240 EnrichedLog net6.0 3.12μs 1.22ns 4.73ns 0.0297 0 0 2.2 KB
#5240 EnrichedLog netcoreapp3.1 4.18μs 1.17ns 4.54ns 0.0292 0 0 2.2 KB
#5240 EnrichedLog net472 4.88μs 1.86ns 7.21ns 0.32 0 0 2.02 KB
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net6.0 1.32μs 1.2ns 4.63ns 0.0159 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.79μs 2.1ns 8.14ns 0.0159 0 0 1.14 KB
master SendReceive net472 2.18μs 6.35ns 24.6ns 0.184 0 0 1.16 KB
#5240 SendReceive net6.0 1.3μs 0.749ns 2.9ns 0.0163 0 0 1.14 KB
#5240 SendReceive netcoreapp3.1 1.79μs 1.1ns 4.26ns 0.0152 0 0 1.14 KB
#5240 SendReceive net472 2.16μs 1.32ns 5.11ns 0.184 0.00108 0 1.16 KB
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.84μs 0.872ns 3.26ns 0.0227 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.99μs 1.39ns 5.2ns 0.0217 0 0 1.65 KB
master EnrichedLog net472 4.39μs 2.09ns 7.8ns 0.322 0 0 2.04 KB
#5240 EnrichedLog net6.0 2.93μs 0.963ns 3.73ns 0.022 0 0 1.6 KB
#5240 EnrichedLog netcoreapp3.1 3.82μs 1.32ns 4.94ns 0.0211 0 0 1.65 KB
#5240 EnrichedLog net472 4.38μs 2.95ns 11.4ns 0.323 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #5240

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1 1.192 788.47 661.19 several?

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 399ns 0.0922ns 0.357ns 0.00801 0 0 576 B
master StartFinishSpan netcoreapp3.1 627ns 0.431ns 1.67ns 0.00789 0 0 576 B
master StartFinishSpan net472 572ns 1.65ns 6.38ns 0.0918 0 0 578 B
master StartFinishScope net6.0 483ns 0.122ns 0.456ns 0.00983 0 0 696 B
master StartFinishScope netcoreapp3.1 786ns 2.7ns 10.5ns 0.00946 0 0 696 B
master StartFinishScope net472 880ns 0.277ns 1.07ns 0.105 0 0 658 B
#5240 StartFinishSpan net6.0 415ns 1.31ns 4.71ns 0.00799 0 0 576 B
#5240 StartFinishSpan netcoreapp3.1 601ns 0.389ns 1.51ns 0.00756 0 0 576 B
#5240 StartFinishSpan net472 604ns 0.386ns 1.5ns 0.0917 0 0 578 B
#5240 StartFinishScope net6.0 485ns 0.444ns 1.72ns 0.00969 0 0 696 B
#5240 StartFinishScope netcoreapp3.1 670ns 3.47ns 17ns 0.00942 0 0 696 B
#5240 StartFinishScope net472 803ns 0.962ns 3.73ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 649ns 0.676ns 2.62ns 0.00972 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 988ns 0.323ns 1.25ns 0.00946 0 0 696 B
master RunOnMethodBegin net472 1.09μs 0.195ns 0.702ns 0.104 0 0 658 B
#5240 RunOnMethodBegin net6.0 641ns 0.566ns 2.19ns 0.00965 0 0 696 B
#5240 RunOnMethodBegin netcoreapp3.1 986ns 3.85ns 14.9ns 0.00958 0 0 696 B
#5240 RunOnMethodBegin net472 1.03μs 1.12ns 4.34ns 0.104 0 0 658 B

@datadog-ddstaging

datadog-ddstaging Bot commented Apr 18, 2024

Copy link
Copy Markdown

Datadog Report

Branch report: chrisnas/support_ssi_telemetry
Commit report: d5c9c99
Test service: dd-trace-dotnet

❌ 519 Failed (6 Known Flaky), 330651 Passed, 1703 Skipped, 41m 14.19s Wall Time

❌ Failed Tests (519)

This report shows up to 5 failed tests.

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

    Expand for error
     Exit code of "Samples.Computer01.exe" should be 0 instead of -1073741819 (= 0xC0000005)
     Expected: True
     Actual:   False
    
  • ExplicitlyDisableAllocationProfiler - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error
     Exit code of "Samples.Computer01.exe" should be 0 instead of -1073741819 (= 0xC0000005)
     Expected: True
     Actual:   False
    
  • MeasureAllocations - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error
     Exit code of "Samples.Computer01.exe" should be 0 instead of -1073741819 (= 0xC0000005)
     Expected: True
     Actual:   False
    
  • MeasureAllocations - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error
     Exit code of "Samples.Computer01.exe" should be 0 instead of -1073741819 (= 0xC0000005)
     Expected: True
     Actual:   False
    
  • ShouldGetAllocationSamples - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error
     Exit code of "Samples.Computer01.exe" should be 0 instead of -1073741819 (= 0xC0000005)
     Expected: True
     Actual:   False
    

@gleocadie
gleocadie force-pushed the chrisnas/support_ssi_telemetry branch from d5c9c99 to 26fff35 Compare May 21, 2024 13:19
@datadog-ddstaging

datadog-ddstaging Bot commented May 21, 2024

Copy link
Copy Markdown

Datadog Report

Branch report: chrisnas/support_ssi_telemetry
Commit report: ae9a761
Test service: dd-trace-dotnet

❌ 2 Failed (0 Known Flaky), 345925 Passed, 2379 Skipped, 24h 9m 40.63s Total Time
⌛ 2 Performance Regressions

❌ Failed Tests (2)

  • CheckSsiAndProfilingSsiEnabled_NoSpan - Datadog.Profiler.IntegrationTests.SingleStepInstrumentation.SingleStepInstrumentationTest - Details

    Expand for error
     Expected nbProfilesSeries to contain only items satisfying the inspector, but collection is empty.
    
  • TestSessionTimeoutVulnerability - Datadog.Trace.Security.IntegrationTests.Iast.AspNetCore5IastTestsRestartedSampleIastEnabled - Details

    Expand for error
     Unable to determine port application is listening on
    

⌛ Performance Regressions vs Default Branch (2)

  • Profiler_garbagecollections - scenarios 2.62s (+92.83ms, +4%) - Details
  • Profiler_walltime - scenarios 4.39s (+50.22ms, +1%) - Details

@gleocadie
gleocadie force-pushed the chrisnas/support_ssi_telemetry branch from f40cb2e to 9b45f89 Compare May 21, 2024 17:36
@gleocadie
gleocadie force-pushed the chrisnas/support_ssi_telemetry branch from 9b45f89 to 6f53476 Compare May 29, 2024 09:04
@gleocadie
gleocadie requested a review from a team as a code owner May 29, 2024 09:04
Comment thread tracer/build/_build/Build.Profiler.Steps.cs Outdated

@andrewlock andrewlock left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just checked the tracing side, I think there's a couple of inconsistencies, but nearly there!

Comment thread tracer/missing-nullability-files.csv Outdated
Comment thread tracer/src/Datadog.Trace/Configuration/TracerSettings.cs
getDefaultValue: () => false,
getDefaultValue: () =>
{
var profilingSsiDeployed = config.WithKeys(ContinuousProfiler.ConfigurationKeys.SsiDeployed).AsString();

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm just wondering, is it useful to explicitly have a difference between ProfilingSsiDeployed and ProfilingEnabled

Comment thread tracer/src/Datadog.Trace/ContinuousProfiler/ProfilerStatus.cs
(fd.OSPlatform == OSPlatformName.Windows && (fd.ProcessArchitecture == ProcessArchitecture.X64 || fd.ProcessArchitecture == ProcessArchitecture.X86)) ||
(fd.OSPlatform == OSPlatformName.Linux && fd.ProcessArchitecture == ProcessArchitecture.X64);

_isProfilingEnabled = false;

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm wondering, what's the impact if the tracer thinks the profiler is enabled and calls EnsureNativeIsIntialized() - does that "enabled" the profiler as expected? Is it as though the profiler was always enabled in that case? 🤔

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Discussed offline - this is fine, though we may refactor at a later point to better represent the profiler status to the tracer (for purposes logging etc)

@andrewlock andrewlock left a comment

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM, thanks!

@chrisnas
chrisnas merged commit 2ebf2cb into master Sep 4, 2024
@chrisnas
chrisnas deleted the chrisnas/support_ssi_telemetry branch September 4, 2024 09:43
@github-actions github-actions Bot added this to the vNext-v3 milestone Sep 4, 2024
andrewlock added a commit that referenced this pull request Sep 11, 2024
## Summary of changes

Fix profiler integration tests in the SSI run

## Reason for change

#5240 changed the behaviour of the profiler in the presence of SSI
variables. We have a scheduled run on master that specifically sets the
variables. This breaks the profiler integration tests that depend on
those variables.

## Implementation details

Add an "environment restorer" attribute, which mirrors the one we use in
the tracing integration tests. Ensures that the SSI tests are working in
their expected environment

## Test coverage

This is the test, but did [a dedicated run
too](https://dev.azure.com/datadoghq/dd-trace-dotnet/_build/results?buildId=163728&view=results),
and it works

## Other details

Related to #6014
andrewlock added a commit that referenced this pull request Sep 12, 2024
## Summary of changes

Fix the diagnostics associated with the expected state of the continuous
profiler

## Reason for change

In #5240, the continuous profiler gained two new "modes" of operation:
delayed enablement based on heuristics, and "monitoring" mode. The tool
should be updated to understand those possibilities + handle it in the
tests

## Implementation details

- Reset the `DD_INJECTION_ENABLED` variable before running the tests -
the presence/absence of the variable changes the expectations, so we
need to account for it
- Explicitly test the various combinations of `DD_INJECTION_ENABLED` and
`DD_PROFILING_ENABLED`.

## Test coverage

Added additional integration and artifact tests

## Other details

This should address most of the issues in the scheduled SSI run. I
suspect the windows integration tests _may_ need additional work, as
currently the profiler library isn't copied to those tests. Will fix in
this PR if that ends up being the case

Supersedes 
- #5991

---------

Co-authored-by: chrisnas <[email protected]>
andrewlock added a commit that referenced this pull request Oct 8, 2024
## Summary of changes

- Set `_NO_DEBUG_HEAP=1` to fix a timeout issue that only happens on
.NET 6, on Windows, on the scheduled SSI run

## Reason for change

We have a weird issue. Ever since
#5240 was merged, the
scheduled SSI run has been failing on .NET 6 `WindowsIntegrationTests`.
The failure is a timeout, because grabbing a stacktrace becomes _crazy_
expensive - it takes ~10s to call `Environment.StackTrace`.

We (@kevingosse) have looked through multiple dumps, and in all cases
we're in the middle of `ConvertPortablePDB`, which is doing a ultimately
calling `RtlCompareMemoryUlong`.

> This method is basically scanning the memory to make sure that
everything is set to `0xFEEEFEEE` - presumably it's the sentinel value
that the heap uses to detect corruption.

<details><summary>Example stack trace</summary>
<pre><code>[0x0] ntdll!RtlCompareMemoryUlong+0x10 0x40f31971a0
0x7ffea493ed15
[0x1]   ntdll!RtlpAllocateHeap+0x9b5   0x40f31971b0   0x7ffea493c4f9   
[0x2] ntdll!RtlpAllocateHeapInternal+0x6c9 0x40f3197380 0x7ffea4a1c7f6
[0x3] ntdll!RtlDebugAllocateHeap+0xf2 0x40f3197490 0x7ffea49d3762
[0x4] ntdll!RtlpAllocateHeap+0x95402 0x40f31974f0 0x7ffea493c4f9
[0x5] ntdll!RtlpAllocateHeapInternal+0x6c9 0x40f31976c0 0x7ffe5dbd9ad8
[0x6] Microsoft_DiaSymReader_Native_amd64!malloc_base+0x44 0x40f31977d0
0x7ffe5dbc2cef
[0x7] Microsoft_DiaSymReader_Native_amd64!operator new+0x1f 0x40f3197800
0x7ffe5dbc3201
[0x8] Microsoft_DiaSymReader_Native_amd64!operator new+0x9 0x40f3197830
0x7ffe5dcf1754
[0x9]
Microsoft_DiaSymReader_Native_amd64!CDebugSSubSectionEnum::Get+0x154
0x40f3197860 0x7ffe5dcc2b79
[0xa]
Microsoft_DiaSymReader_Native_amd64!Mod1::fUpdateTiOrIdReferencedByNonSyms+0x119
0x40f3197890 0x7ffe5dcc4a2b
[0xb] Microsoft_DiaSymReader_Native_amd64!Mod1::processC13+0x14b
0x40f3197920 0x7ffe5dcc165e
[0xc] Microsoft_DiaSymReader_Native_amd64!Mod1::fProcessSyms+0x126e
0x40f3197bd0 0x7ffe5dcc2a3b
[0xd] Microsoft_DiaSymReader_Native_amd64!Mod1::fUpdateSyms+0x1b
0x40f3197c90 0x7ffe5dcb81cb
[0xe] Microsoft_DiaSymReader_Native_amd64!Mod1::Close+0x1eb 0x40f3197cc0
0x7ffe5dc9d3d3
[0xf]
Microsoft_DiaSymReader_Native_amd64!PortablePDB::ConvertPortablePDB+0x463
0x40f3197d30 0x7ffe5dc86c6e
[0x10] Microsoft_DiaSymReader_Native_amd64!PDB1::OpenPortablePDB+0x9e
0x40f3198670 0x7ffe5dc85c41
[0x11] Microsoft_DiaSymReader_Native_amd64!PDB1::OpenEx2W+0x621
0x40f31986e0 0x7ffe5dc875fe
[0x12] Microsoft_DiaSymReader_Native_amd64!PDB1::OpenValidate4+0x8e
0x40f31987a0 0x7ffe5dcd2a2b
[0x13] Microsoft_DiaSymReader_Native_amd64!LOCATOR::FOpenValidate4+0x8b
0x40f3198850 0x7ffe5dcd1c34
[0x14] Microsoft_DiaSymReader_Native_amd64!LOCATOR::FLocatePdb+0x144
0x40f3198f00 0x7ffe5dc996da
[0x15] Microsoft_DiaSymReader_Native_amd64!PDBCommon::OpenValidate7+0xea
0x40f3199ff0 0x7ffe5dbe847b
[0x16]
Microsoft_DiaSymReader_Native_amd64!CDiaDataSource::loadDataForExeHelper+0xab
0x40f319ae00 0x7ffe5dbe8305
[0x17]
Microsoft_DiaSymReader_Native_amd64!CDiaDataSource::loadDataForExeEx3+0x35
0x40f319af90 0x7ffe5dbb8c78
[0x18] Microsoft_DiaSymReader_Native_amd64!sh::CDiaWrapper::Create+0x158
0x40f319afe0 0x7ffe5dba9bf4
[0x19]
Microsoft_DiaSymReader_Native_amd64!sh::SymReader::InitWithRestrictedSearch+0x94
0x40f319b060 0x7ffe5dbb092e
[0x1a]
Microsoft_DiaSymReader_Native_amd64!sh::SymBinder::GetReaderForFile+0xae
0x40f319b090 0x7ffe8b40852e
[0x1b] coreclr!Module::GetISymUnmanagedReader+0x7ce 0x40f319b0d0
0x7ffe8b4089d2
[0x1c] coreclr!Module::GetISymUnmanagedReaderNoThrow+0x72 0x40f319b320
0x7ffe8b4153e3
[0x1d] coreclr!DebugStackTrace::GetStackFramesInternal+0xa83
0x40f319b3c0 0x7ffe607bb1c2
[0x1e]
System_Private_CoreLib!System.Diagnostics.StackFrameHelper.InitializeSourceInfo+0x42
0x40f319be00 0x7ffe607bb912
[0x1f]
System_Private_CoreLib!System.Diagnostics.StackTrace.CaptureStackTrace+0x42
0x40f319bf00 0x7ffe607bba03
[0x20] System_Private_CoreLib!System.Diagnostics.StackTrace..ctor+0x13
0x40f319bf60 0x7ffe605b431c
[0x21] System_Private_CoreLib!System.Environment.get_StackTrace+0x1c
0x40f319bf90 0x7ffe2bb15da0
[0x22]
Datadog_Trace!Datadog.Trace.Logging.DatadogLogging.GetLoggerFor+0x80
0x40f319bfc0 0x257516f648550000
[0x23]   0x257516f648550000!+   0x40f319bfc8   0x1c8fc9e9000   
[0x24]   0x1c8fc9e9000!+   0x40f319bfd0   0x1c8fd1951c0   
[0x25]   0x1c8fd1951c0!+   0x40f319bfd8   0x1c8fd1951c0   
[0x26]   0x1c8fd1951c0!+   0x40f319bfe0   0x8b267570   
[0x27]   0x8b267570!+   0x40f319bfe8   0x7ffe2b8085a8   
[0x28]   0x7ffe2b8085a8!+   0x40f319bff0   0x40f319c2c8   
[0x29]   0x40f319c2c8!+   0x40f319bff8   0x1c880076070   
[0x2a]   0x1c880076070!+   0x40f319c000   0x0   
</code></pre>
</details> 

What is really weird is the fact that this _only_ happens

- When the SSI variables are enabled (`DD_INJECTION_ENABLED` is set)
- When procdump is attached to capture dumps
- When it's .NET 6, Windows (not .NET 7+, not Linux)

Testing shows that not attaching procdump solves it.

Even more confusing, I _can_ reproduce locally using the following:

```csharp
$env:enable_crash_dumps="true"
.\tracer\build.ps1 BuildTracerHome
.\tracer\build.ps1 BuildAndRunWindowsIntegrationTests --framework net6.0 --filter HttpMessageHandlerTests.HttpClient_SubmitsTraces --sample-name Samples.HttpMessageHandler
```

Note that _locally_ I don't even need to enable the SSI variables 😕 

No, none of this makes any sense to me, I've been digging into this for
days now 🤦‍♂️

The only thing that 100% causes it is procdump. And setting
`_NO_DEBUG_HEAP=1` [disables the debug allocate heap, which solves
it](https://preshing.com/20110717/the-windows-heap-is-slow-when-launched-from-the-debugger/).

I'd _love_ to figure this one out, but given this doesn't _seem_ like it
should be a prod issue, taking the easy option right now, until we can
work out what it is about
#5240 that it doesn't
like 🤷‍♂️

## Test coverage

[I'll trigger a full SSI run to make sure it _is_
solved](https://dev.azure.com/datadoghq/dd-trace-dotnet/_build/results?buildId=165153&view=results)

## Other details

Note that in the Windows integration tests, the profiler isn't
_actually_ available, because we don't download it. But that doesn't
seem to make a difference, because locally when the profiler is there I
still repro
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:profiler Issues related to the continous-profiler

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants