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

[WIP] Add simple log statement at serialization to get SamplingPriority

Open bouwkast opened this issue 1 year ago • 4 comments

Summary of changes

Just adding logging statements closer toward serialization to try and get SamplingPriority.

Reason for change

Sampling priority doesn't get logged out and could be helpful for investigations where we seem to be missing spans.

Implementation details

Test coverage

Other details

bouwkast avatar Jan 22 '24 21:01 bouwkast

Datadog Report

Branch report: steven/debug-logs Commit report: 007db97 Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 273912 Passed, 1411 Skipped, 1h 0m 37.3s Wall Time

datadog-ddstaging[bot] avatar Jan 22 '24 21:01 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 (5098) - mean (71ms)  : 61, 80
     .   : milestone, 71,
    master - mean (72ms)  : 61, 83
     .   : milestone, 72,

    section CallTarget+Inlining+NGEN
    This PR (5098) - mean (958ms)  : 935, 980
     .   : milestone, 958,
    master - mean (944ms)  : 918, 971
     .   : milestone, 944,


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

    section CallTarget+Inlining+NGEN
    This PR (5098) - mean (696ms)  : 672, 719
     .   : milestone, 696,
    master - mean (692ms)  : 670, 714
     .   : milestone, 692,


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

    section CallTarget+Inlining+NGEN
    This PR (5098) - mean (652ms)  : 636, 668
     .   : milestone, 652,
    master - mean (645ms)  : 624, 665
     .   : milestone, 645,


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

    section CallTarget+Inlining+NGEN
    This PR (5098) - mean (1,069ms)  : 1049, 1089
     .   : milestone, 1069,
    master - mean (1,068ms)  : 1042, 1094
     .   : milestone, 1068,


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

    section CallTarget+Inlining+NGEN
    This PR (5098) - mean (1,055ms)  : 1029, 1082
     .   : milestone, 1055,
    master - mean (1,057ms)  : 1033, 1080
     .   : milestone, 1057,


gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (5098) - mean (262ms)  : 258, 266
     .   : milestone, 262,
    master - mean (262ms)  : 258, 266
     .   : milestone, 262,

    section CallTarget+Inlining+NGEN
    This PR (5098) - mean (1,016ms)  : 997, 1034
     .   : milestone, 1016,
    master - mean (1,023ms)  : 1002, 1044
     .   : milestone, 1023,

andrewlock avatar Jan 22 '24 21:01 andrewlock

Benchmarks Report :snail:

Benchmarks for #5098 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.135
  • 2 benchmarks are slower, with geometric mean 1.131
  • 2 benchmarks have fewer allocations
  • 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 :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.68μs 47.8ns 283ns 0.0216 0.00866 0 7.48 KB
master StartStopWithChild netcoreapp3.1 10.6μs 45.4ns 192ns 0.037 0.0158 0 7.58 KB
master StartStopWithChild net472 17.2μs 53ns 205ns 1.33 0.349 0.111 7.95 KB
#5098 StartStopWithChild net6.0 8.81μs 49.9ns 346ns 0.0181 0.00453 0 7.48 KB
#5098 StartStopWithChild netcoreapp3.1 11.1μs 53.1ns 314ns 0.0355 0.0152 0 7.58 KB
#5098 StartStopWithChild net472 17.5μs 47.1ns 182ns 1.35 0.354 0.104 7.96 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 478μs 255ns 955ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 634μs 326ns 1.26μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 804μs 158ns 548ns 0.401 0 0 3.3 KB
#5098 WriteAndFlushEnrichedTraces net6.0 455μs 255ns 952ns 0 0 0 2.7 KB
#5098 WriteAndFlushEnrichedTraces netcoreapp3.1 640μs 342ns 1.32μs 0 0 0 2.7 KB
#5098 WriteAndFlushEnrichedTraces net472 801μs 347ns 1.3μs 0.396 0 0 3.3 KB
Benchmarks.Trace.Asm.AppSecBodyBenchmark - 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 AllCycleSimpleBody net6.0 39.4μs 45.3ns 169ns 0.0198 0 0 1.77 KB
master AllCycleSimpleBody netcoreapp3.1 41.2μs 30.9ns 116ns 0.0208 0 0 1.74 KB
master AllCycleSimpleBody net472 44.8μs 19.9ns 71.7ns 0.27 0 0 1.81 KB
master AllCycleMoreComplexBody net6.0 201μs 71.6ns 277ns 0.1 0 0 9.25 KB
master AllCycleMoreComplexBody netcoreapp3.1 217μs 214ns 829ns 0.106 0 0 9.14 KB
master AllCycleMoreComplexBody net472 226μs 117ns 454ns 1.47 0 0 9.32 KB
master ObjectExtractorSimpleBody net6.0 142ns 0.143ns 0.556ns 0.00396 0 0 280 B
master ObjectExtractorSimpleBody netcoreapp3.1 203ns 0.223ns 0.864ns 0.00369 0 0 272 B
master ObjectExtractorSimpleBody net472 173ns 0.133ns 0.48ns 0.0446 0 0 281 B
master ObjectExtractorMoreComplexBody net6.0 3.05μs 4.09ns 15.3ns 0.0533 0 0 3.78 KB
master ObjectExtractorMoreComplexBody netcoreapp3.1 3.95μs 1.55ns 5.81ns 0.0495 0 0 3.69 KB
master ObjectExtractorMoreComplexBody net472 3.98μs 5.01ns 18.7ns 0.602 0.00593 0 3.8 KB
#5098 AllCycleSimpleBody net6.0 38.2μs 18.2ns 70.7ns 0.0193 0 0 1.77 KB
#5098 AllCycleSimpleBody netcoreapp3.1 42.2μs 54ns 202ns 0.021 0 0 1.74 KB
#5098 AllCycleSimpleBody net472 44.7μs 7.98ns 27.6ns 0.269 0 0 1.81 KB
#5098 AllCycleMoreComplexBody net6.0 198μs 136ns 527ns 0.0987 0 0 9.25 KB
#5098 AllCycleMoreComplexBody netcoreapp3.1 211μs 275ns 1.07μs 0.105 0 0 9.14 KB
#5098 AllCycleMoreComplexBody net472 226μs 85.2ns 330ns 1.47 0 0 9.32 KB
#5098 ObjectExtractorSimpleBody net6.0 142ns 0.136ns 0.507ns 0.00391 0 0 280 B
#5098 ObjectExtractorSimpleBody netcoreapp3.1 198ns 0.121ns 0.437ns 0.00371 0 0 272 B
#5098 ObjectExtractorSimpleBody net472 171ns 0.087ns 0.326ns 0.0446 0 0 281 B
#5098 ObjectExtractorMoreComplexBody net6.0 3.06μs 2.56ns 9.9ns 0.0529 0 0 3.78 KB
#5098 ObjectExtractorMoreComplexBody netcoreapp3.1 4.05μs 2.27ns 8.5ns 0.0505 0 0 3.69 KB
#5098 ObjectExtractorMoreComplexBody net472 3.87μs 2.84ns 10.6ns 0.602 0.00581 0 3.8 KB
Benchmarks.Trace.Asm.AppSecWafBenchmark - 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 RunWaf(args=NestedMap (10)) net6.0 54.2μs 25.7ns 96.1ns 0.222 0 0 16.06 KB
master RunWaf(args=NestedMap (10)) netcoreapp3.1 64.7μs 53.9ns 194ns 0.194 0 0 16.06 KB
master RunWaf(args=NestedMap (10)) net472 100μs 487ns 2.07μs 2.54 0.0959 0 16.14 KB
master RunWafTwice(args=NestedMap (10)) net6.0 57.7μs 306ns 1.62μs 0.234 0 0 16.6 KB
master RunWafTwice(args=NestedMap (10)) netcoreapp3.1 71.1μs 265ns 957ns 0.212 0 0 16.58 KB
master RunWafTwice(args=NestedMap (10)) net472 107μs 494ns 1.91μs 2.63 0.107 0 16.69 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 112μs 77.6ns 301ns 0.295 0 0 22.41 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 133μs 679ns 3.18μs 0.256 0 0 22.36 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net472 164μs 761ns 2.95μs 3.55 0.161 0 22.7 KB
master RunWaf(args=NestedMap (100)) net6.0 105μs 220ns 851ns 0.417 0 0 32.76 KB
master RunWaf(args=NestedMap (100)) netcoreapp3.1 133μs 315ns 1.22μs 0.402 0 0 33.33 KB
master RunWaf(args=NestedMap (100)) net472 195μs 150ns 562ns 5.27 0.37 0 33.67 KB
master RunWafTwice(args=NestedMap (100)) net6.0 107μs 339ns 1.27μs 0.428 0 0 33.3 KB
master RunWafTwice(args=NestedMap (100)) netcoreapp3.1 141μs 127ns 493ns 0.413 0 0 33.86 KB
master RunWafTwice(args=NestedMap (100)) net472 201μs 607ns 2.35μs 5.44 0.396 0 34.22 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) net6.0 162μs 56.1ns 210ns 0.517 0 0 39.1 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) netcoreapp3.1 204μs 385ns 1.49μs 0.488 0 0 39.63 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) net472 253μs 140ns 485ns 6.38 0.51 0 40.23 KB
master RunWaf(args=NestedMap (20)) net6.0 109μs 14ns 52.2ns 0.453 0 0 32.18 KB
master RunWaf(args=NestedMap (20)) netcoreapp3.1 134μs 437ns 1.69μs 0.438 0 0 32.3 KB
master RunWaf(args=NestedMap (20)) net472 188μs 904ns 3.62μs 5.1 0.371 0 32.63 KB
master RunWafTwice(args=NestedMap (20)) net6.0 103μs 34ns 123ns 0.464 0 0 32.72 KB
master RunWafTwice(args=NestedMap (20)) netcoreapp3.1 138μs 725ns 3.7μs 0.399 0 0 32.82 KB
master RunWafTwice(args=NestedMap (20)) net472 198μs 857ns 3.32μs 5.22 0.386 0 33.19 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 161μs 149ns 515ns 0.543 0 0 38.53 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 198μs 80.2ns 289ns 0.512 0 0 38.6 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net472 256μs 1.1μs 4.27μs 6.21 0.507 0 39.2 KB
#5098 RunWaf(args=NestedMap (10)) net6.0 57.1μs 43ns 155ns 0.229 0 0 16.06 KB
#5098 RunWaf(args=NestedMap (10)) netcoreapp3.1 71.3μs 375ns 1.87μs 0.216 0 0 16.06 KB
#5098 RunWaf(args=NestedMap (10)) net472 98.8μs 36.5ns 141ns 2.54 0.0959 0 16.14 KB
#5098 RunWafTwice(args=NestedMap (10)) net6.0 53μs 30.4ns 110ns 0.234 0 0 16.6 KB
#5098 RunWafTwice(args=NestedMap (10)) netcoreapp3.1 74.5μs 411ns 2.67μs 0.22 0 0 16.58 KB
#5098 RunWafTwice(args=NestedMap (10)) net472 104μs 34.5ns 134ns 2.65 0.104 0 16.69 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 113μs 122ns 473ns 0.285 0 0 22.41 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 129μs 160ns 597ns 0.255 0 0 22.36 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [22]) net472 163μs 790ns 3.26μs 3.59 0.159 0 22.7 KB
#5098 RunWaf(args=NestedMap (100)) net6.0 107μs 488ns 1.89μs 0.423 0 0 32.76 KB
#5098 RunWaf(args=NestedMap (100)) netcoreapp3.1 135μs 686ns 3.36μs 0.443 0 0 33.33 KB
#5098 RunWaf(args=NestedMap (100)) net472 184μs 92.2ns 345ns 5.31 0.366 0 33.67 KB
#5098 RunWafTwice(args=NestedMap (100)) net6.0 106μs 589ns 3.82μs 0.449 0 0 33.3 KB
#5098 RunWafTwice(args=NestedMap (100)) netcoreapp3.1 141μs 405ns 1.57μs 0.46 0 0 33.86 KB
#5098 RunWafTwice(args=NestedMap (100)) net472 201μs 147ns 570ns 5.43 0.388 0 34.22 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [23]) net6.0 160μs 77.9ns 281ns 0.51 0 0 39.1 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [23]) netcoreapp3.1 200μs 869ns 3.37μs 0.494 0 0 39.63 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [23]) net472 261μs 111ns 428ns 6.39 0.511 0 40.23 KB
#5098 RunWaf(args=NestedMap (20)) net6.0 111μs 84ns 314ns 0.447 0 0 32.18 KB
#5098 RunWaf(args=NestedMap (20)) netcoreapp3.1 135μs 175ns 678ns 0.441 0 0 32.3 KB
#5098 RunWaf(args=NestedMap (20)) net472 187μs 286ns 1.11μs 5.15 0.375 0 32.63 KB
#5098 RunWafTwice(args=NestedMap (20)) net6.0 110μs 69.7ns 270ns 0.442 0 0 32.72 KB
#5098 RunWafTwice(args=NestedMap (20)) netcoreapp3.1 138μs 737ns 4.1μs 0.42 0 0 32.82 KB
#5098 RunWafTwice(args=NestedMap (20)) net472 200μs 560ns 2.17μs 5.24 0.388 0 33.19 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 165μs 863ns 4.48μs 0.55 0 0 38.53 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 208μs 312ns 1.21μs 0.491 0 0 38.6 KB
#5098 RunWafWithAttack(args=Neste(...)tack) [22]) net472 262μs 341ns 1.32μs 6.13 0.522 0 39.2 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 173μs 145ns 563ns 0.171 0 0 18.25 KB
master SendRequest netcoreapp3.1 195μs 222ns 831ns 0.192 0 0 20.41 KB
master SendRequest net472 0.000948ns 0.000384ns 0.00149ns 0 0 0 0 b
#5098 SendRequest net6.0 173μs 143ns 533ns 0.171 0 0 18.25 KB
#5098 SendRequest netcoreapp3.1 195μs 389ns 1.51μs 0.193 0 0 20.42 KB
#5098 SendRequest net472 0.000168ns 0.000146ns 0.000567ns 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 554μs 196ns 759ns 0.556 0 0 41.72 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 659μs 1.82μs 7.03μs 0.329 0 0 41.65 KB
master WriteAndFlushEnrichedTraces net472 840μs 3.5μs 12.6μs 8.45 2.53 0.422 53.23 KB
#5098 WriteAndFlushEnrichedTraces net6.0 549μs 472ns 1.7μs 0.548 0 0 41.67 KB
#5098 WriteAndFlushEnrichedTraces netcoreapp3.1 653μs 2.48μs 9.61μs 0.334 0 0 41.68 KB
#5098 WriteAndFlushEnrichedTraces net472 821μs 2.84μs 11μs 8.12 2.44 0.406 53.24 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.1μs 0.84ns 3.25ns 0.0104 0 0 768 B
master ExecuteNonQuery netcoreapp3.1 1.51μs 1.01ns 3.89ns 0.0106 0 0 768 B
master ExecuteNonQuery net472 1.83μs 1.36ns 5.08ns 0.116 0 0 730 B
#5098 ExecuteNonQuery net6.0 1.16μs 0.694ns 2.5ns 0.0106 0 0 768 B
#5098 ExecuteNonQuery netcoreapp3.1 1.54μs 1.3ns 5.04ns 0.00978 0 0 768 B
#5098 ExecuteNonQuery net472 1.76μs 0.793ns 2.86ns 0.115 0 0 730 B
Benchmarks.Trace.ElasticsearchBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #5098

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync‑netcoreapp3.1 1.122 1,794.38 1,598.81

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.23μs 1.41ns 5.28ns 0.0128 0 0 936 B
master CallElasticsearch netcoreapp3.1 1.51μs 0.703ns 2.63ns 0.0129 0 0 936 B
master CallElasticsearch net472 2.48μs 0.801ns 3.1ns 0.151 0 0 955 B
master CallElasticsearchAsync net6.0 1.41μs 1.47ns 5.68ns 0.0128 0 0 912 B
master CallElasticsearchAsync netcoreapp3.1 1.79μs 5.2ns 18.8ns 0.013 0 0 984 B
master CallElasticsearchAsync net472 2.78μs 2.4ns 8.99ns 0.16 0 0 1.01 KB
#5098 CallElasticsearch net6.0 1.25μs 0.57ns 2.13ns 0.0132 0 0 936 B
#5098 CallElasticsearch netcoreapp3.1 1.48μs 1.06ns 4.09ns 0.0126 0 0 936 B
#5098 CallElasticsearch net472 2.55μs 0.783ns 2.93ns 0.152 0 0 955 B
#5098 CallElasticsearchAsync net6.0 1.32μs 0.507ns 1.9ns 0.0125 0 0 912 B
#5098 CallElasticsearchAsync netcoreapp3.1 1.6μs 0.939ns 3.51ns 0.0137 0 0 984 B
#5098 CallElasticsearchAsync net472 2.71μs 6.65ns 25.7ns 0.16 0 0 1.01 KB
Benchmarks.Trace.GraphQLBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #5098

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0 1.116 1,243.37 1,387.50

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.25μs 3.06ns 13.3ns 0.0127 0 0 912 B
master ExecuteAsync netcoreapp3.1 1.66μs 2.35ns 8.78ns 0.0124 0 0 912 B
master ExecuteAsync net472 1.71μs 1.12ns 4.33ns 0.139 0 0 875 B
#5098 ExecuteAsync net6.0 1.39μs 0.572ns 2.14ns 0.0123 0 0 912 B
#5098 ExecuteAsync netcoreapp3.1 1.67μs 1.98ns 7.67ns 0.0124 0 0 912 B
#5098 ExecuteAsync net472 1.87μs 1.4ns 5.43ns 0.139 0 0 875 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μs 1.76ns 6.83ns 0.0301 0 0 2.1 KB
master SendAsync netcoreapp3.1 4.95μs 1.59ns 5.94ns 0.0346 0 0 2.63 KB
master SendAsync net472 7.65μs 3.09ns 12ns 0.524 0 0 3.31 KB
#5098 SendAsync net6.0 4.17μs 3.02ns 11.3ns 0.0297 0 0 2.1 KB
#5098 SendAsync netcoreapp3.1 4.86μs 1.58ns 6.12ns 0.0342 0 0 2.63 KB
#5098 SendAsync net472 7.64μs 3.45ns 13.4ns 0.523 0 0 3.31 KB
Benchmarks.Trace.Iast.StringAspectsBenchmark - Same speed :heavy_check_mark: More allocations :warning:

More allocations :warning: in #5098

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑netcoreapp3.1 200.89 KB 211.54 KB 10.65 KB 5.30%

Fewer allocations :tada: in #5098

Benchmark Base Allocated Diff Allocated Change Change %
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark‑net472 61.25 KB 59.07 KB -2.18 KB -3.55%
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark‑net6.0 214.22 KB 202.27 KB -11.95 KB -5.58%

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StringConcatBenchmark net6.0 60.4μs 1.01μs 10μs 0 0 0 43.44 KB
master StringConcatBenchmark netcoreapp3.1 53.2μs 215ns 745ns 0 0 0 42.64 KB
master StringConcatBenchmark net472 37.6μs 128ns 461ns 0 0 0 61.25 KB
master StringConcatAspectBenchmark net6.0 290μs 1.99μs 19.1μs 0 0 0 214.22 KB
master StringConcatAspectBenchmark netcoreapp3.1 284μs 2.62μs 24μs 0 0 0 200.89 KB
master StringConcatAspectBenchmark net472 244μs 4.02μs 38.6μs 0 0 0 221.18 KB
#5098 StringConcatBenchmark net6.0 63.3μs 960ns 9.31μs 0 0 0 43.44 KB
#5098 StringConcatBenchmark netcoreapp3.1 53.3μs 223ns 833ns 0 0 0 42.64 KB
#5098 StringConcatBenchmark net472 37.5μs 93.9ns 339ns 0 0 0 59.07 KB
#5098 StringConcatAspectBenchmark net6.0 292μs 3.28μs 29.8μs 0 0 0 202.27 KB
#5098 StringConcatAspectBenchmark netcoreapp3.1 281μs 2.39μs 21.8μs 0 0 0 211.54 KB
#5098 StringConcatAspectBenchmark net472 254μs 4.99μs 48.4μs 0 0 0 221.18 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.42μs 0.512ns 1.84ns 0.0221 0 0 1.57 KB
master EnrichedLog netcoreapp3.1 2.25μs 1.27ns 4.57ns 0.0214 0 0 1.57 KB
master EnrichedLog net472 2.74μs 4.28ns 16.6ns 0.237 0 0 1.5 KB
#5098 EnrichedLog net6.0 1.42μs 0.761ns 2.85ns 0.022 0 0 1.57 KB
#5098 EnrichedLog netcoreapp3.1 2.31μs 1.47ns 5.69ns 0.0209 0 0 1.57 KB
#5098 EnrichedLog net472 2.58μs 2.82ns 10.9ns 0.237 0 0 1.5 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 113μs 116ns 449ns 0 0 0 4.21 KB
master EnrichedLog netcoreapp3.1 117μs 132ns 511ns 0.0591 0 0 4.21 KB
master EnrichedLog net472 149μs 70.7ns 274ns 0.668 0.223 0 4.39 KB
#5098 EnrichedLog net6.0 113μs 168ns 649ns 0.0566 0 0 4.21 KB
#5098 EnrichedLog netcoreapp3.1 119μs 165ns 597ns 0 0 0 4.21 KB
#5098 EnrichedLog net472 148μs 108ns 418ns 0.669 0.223 0 4.39 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.08μs 0.662ns 2.48ns 0.0293 0 0 2.13 KB
master EnrichedLog netcoreapp3.1 4.19μs 1.89ns 7.06ns 0.0273 0 0 2.13 KB
master EnrichedLog net472 4.87μs 1.95ns 7.56ns 0.308 0 0 1.95 KB
#5098 EnrichedLog net6.0 2.94μs 1.25ns 4.84ns 0.03 0 0 2.13 KB
#5098 EnrichedLog netcoreapp3.1 4.28μs 1.96ns 7.05ns 0.0277 0 0 2.13 KB
#5098 EnrichedLog net472 4.8μs 2.01ns 7.52ns 0.307 0 0 1.95 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.32μs 0.554ns 2.14ns 0.0152 0 0 1.1 KB
master SendReceive netcoreapp3.1 1.75μs 0.533ns 1.99ns 0.0151 0 0 1.1 KB
master SendReceive net472 2.09μs 1.52ns 5.69ns 0.176 0 0 1.12 KB
#5098 SendReceive net6.0 1.32μs 0.805ns 3.12ns 0.0151 0 0 1.1 KB
#5098 SendReceive netcoreapp3.1 1.74μs 1.72ns 6.66ns 0.0148 0 0 1.1 KB
#5098 SendReceive net472 2.12μs 2ns 7.76ns 0.177 0 0 1.12 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.97μs 1.7ns 6.58ns 0.0208 0 0 1.53 KB
master EnrichedLog netcoreapp3.1 3.95μs 1.8ns 6.97ns 0.0197 0 0 1.58 KB
master EnrichedLog net472 4.4μs 1.91ns 7.13ns 0.312 0 0 1.97 KB
#5098 EnrichedLog net6.0 2.72μs 0.843ns 3.26ns 0.0206 0 0 1.53 KB
#5098 EnrichedLog netcoreapp3.1 3.78μs 1.52ns 5.9ns 0.0207 0 0 1.58 KB
#5098 EnrichedLog net472 4.28μs 1.16ns 4.5ns 0.312 0 0 1.97 KB
Benchmarks.Trace.SpanBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #5098

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.149 514.11 447.54

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 514ns 0.212ns 0.819ns 0.00757 0 0 536 B
master StartFinishSpan netcoreapp3.1 656ns 0.392ns 1.52ns 0.00715 0 0 536 B
master StartFinishSpan net472 808ns 0.203ns 0.76ns 0.0853 0 0 538 B
master StartFinishScope net6.0 627ns 0.208ns 0.78ns 0.00899 0 0 656 B
master StartFinishScope netcoreapp3.1 834ns 0.485ns 1.88ns 0.00878 0 0 656 B
master StartFinishScope net472 963ns 0.429ns 1.66ns 0.0979 0 0 618 B
#5098 StartFinishSpan net6.0 448ns 0.263ns 1.02ns 0.00747 0 0 536 B
#5098 StartFinishSpan netcoreapp3.1 681ns 0.479ns 1.86ns 0.00715 0 0 536 B
#5098 StartFinishSpan net472 756ns 0.787ns 3.05ns 0.0854 0 0 538 B
#5098 StartFinishScope net6.0 575ns 0.162ns 0.627ns 0.00923 0 0 656 B
#5098 StartFinishScope netcoreapp3.1 808ns 0.305ns 1.18ns 0.00887 0 0 656 B
#5098 StartFinishScope net472 1μs 0.458ns 1.77ns 0.0981 0 0 618 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower :warning: Same allocations :heavy_check_mark:

Slower :warning: in #5098

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 1.147 569.26 652.87

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 569ns 0.162ns 0.627ns 0.00933 0 0 656 B
master RunOnMethodBegin netcoreapp3.1 960ns 0.758ns 2.94ns 0.00871 0 0 656 B
master RunOnMethodBegin net472 1.06μs 0.363ns 1.41ns 0.0978 0 0 618 B
#5098 RunOnMethodBegin net6.0 653ns 0.324ns 1.25ns 0.00916 0 0 656 B
#5098 RunOnMethodBegin netcoreapp3.1 986ns 1.34ns 5.18ns 0.00876 0 0 656 B
#5098 RunOnMethodBegin net472 1.14μs 0.177ns 0.686ns 0.0979 0 0 618 B

andrewlock avatar Jan 23 '24 00:01 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 (5098) (11.051M)   : 0, 11051273
    master (11.078M)   : 0, 11078217
    benchmarks/2.9.0 (11.015M)   : 0, 11014948

    section Automatic
    This PR (5098) (7.521M)   : 0, 7520762
    master (7.478M)   : 0, 7478193
    benchmarks/2.9.0 (7.926M)   : 0, 7925773

    section Trace stats
    This PR (5098) (7.823M)   : 0, 7822613
    master (7.957M)   : 0, 7956885

    section Manual
    This PR (5098) (9.473M)   : 0, 9472764
    master (9.693M)   : 0, 9692849

    section Manual + Automatic
    This PR (5098) (7.074M)   : 0, 7073525
    master (7.162M)   : 0, 7161560

    section Version Conflict
    This PR (5098) (6.412M)   : 0, 6412103
    master (6.527M)   : 0, 6527327


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5098) (9.519M)   : 0, 9519300
    master (9.511M)   : 0, 9511060
    benchmarks/2.9.0 (9.652M)   : 0, 9651615

    section Automatic
    This PR (5098) (6.584M)   : 0, 6584273
    master (6.731M)   : 0, 6730572

    section Trace stats
    This PR (5098) (6.798M)   : 0, 6798114
    master (6.843M)   : 0, 6842643

    section Manual
    This PR (5098) (8.139M)   : 0, 8139087
    master (8.329M)   : 0, 8329261

    section Manual + Automatic
    This PR (5098) (5.895M)   : crit ,0, 5894764
    master (6.241M)   : 0, 6241377

    section Version Conflict
    This PR (5098) (5.778M)   : 0, 5777719
    master (5.733M)   : 0, 5732704


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (5098) (9.921M)   : 0, 9920890
    master (10.008M)   : 0, 10007628
    benchmarks/2.9.0 (10.371M)   : 0, 10371072

    section Automatic
    This PR (5098) (7.026M)   : 0, 7026431
    master (7.094M)   : 0, 7093941
    benchmarks/2.9.0 (7.518M)   : 0, 7518013

    section Trace stats
    This PR (5098) (7.313M)   : 0, 7313363
    master (7.321M)   : 0, 7320885

    section Manual
    This PR (5098) (8.862M)   : 0, 8862142
    master (8.839M)   : 0, 8838799

    section Manual + Automatic
    This PR (5098) (6.773M)   : 0, 6772511
    master (6.905M)   : 0, 6904693

    section Version Conflict
    This PR (5098) (6.035M)   : 0, 6035093
    master (6.177M)   : 0, 6176842


gantt
    title Throughput Linux x64 (ASM) (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    master (7.477M)   : 0, 7476892
    benchmarks/2.9.0 (7.958M)   : 0, 7957509

    section No attack
    master (1.770M)   : 0, 1770190
    benchmarks/2.9.0 (3.247M)   : 0, 3247318

    section Attack
    master (1.399M)   : 0, 1398783
    benchmarks/2.9.0 (2.539M)   : 0, 2539306

    section Blocking
    master (3.092M)   : 0, 3092380

    section IAST default
    master (6.527M)   : 0, 6527052

    section IAST full
    master (5.701M)   : 0, 5700591

    section Base vuln
    master (0.938M)   : 0, 937685

    section IAST vuln
    master (0.865M)   : 0, 864967

andrewlock avatar Jan 23 '24 00:01 andrewlock