Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Add de-duplication of telemetry logs #4835

Merged
merged 1 commit into from
Nov 15, 2023
Merged

Add de-duplication of telemetry logs #4835

merged 1 commit into from
Nov 15, 2023

Conversation

andrewlock
Copy link
Member

@andrewlock andrewlock commented Nov 8, 2023 •
edited
Loading

Summary of changes

Adds de-duplication of error messages

Reason for change

We want to de-duplicate errors as much as possible to reduce load. Given that we're only using the (static) message templates and the redacted stack traces, we should be able to get significant reducations.

Implementation details

Uses the message template (+ stack trace if present) to generate a hash. Check if the hash has already been seen before writing the log message.

Ideally we would do this check in the sink rather than the collector. But the collector needs to know the "latest" counts for a log so that it can add it to the payload when the logs are sent, hence the current implementation.

This implementation will need to be updated with the number of times the log was seen, once the intake supports it. We could add a suffix to the message but hopefully the intake will just support it directly soon.

When a new batch is emitted, we reset the log count. Technically I think there's a small race condition which would cause a duplicate log message to be "dropped" entirely under the following conditions:

  • The log message (MESSAGE) has been previously seen 3 times (it's present in the logCounts dictionary).
  • EnqueueLog is called, which takes a reference to the logCounts dictionary
  • EmitBatch swaps out the dictionary, and starts processing the log messages in the batch, adding the counts. It records the log message for MESSAGE with the existing count (3)
  • EnqueueLog checks its logCounts dictionary, updates the count to 4, and discards the log
  • The "wrong" count is sent.

Ideally we would either send the correct count, 4, or we would emit the log in the next batch. However, I don't think this is a big enough issue to worry about (unless there's an easy solution I'm missing)!

Test coverage

Updated tests to check the deduplication works as expected

Other details

Supersedes (and re-implements):

Part 4 in a stack of PRs

@andrewlock andrewlock requested a review from a team as a code owner November 8, 2023 14:59
This was referenced Nov 8, 2023
Merged
Merged
Merged
@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Nov 8, 2023 •
edited
Loading

Datadog Report

Branch report: andrew/telemetry/redacted-logs
Commit report: 4b02d72

✅ dd-trace-dotnet: 0 Failed, 0 New Flaky, 300317 Passed, 967 Skipped, 30m 54.76s Wall Time

@andrewlock
Copy link
Member Author

andrewlock commented Nov 8, 2023 •
edited
Loading

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 (4835) - mean (72ms)  : 61, 82
     .   : milestone, 72,
    master - mean (67ms)  : 65, 70
     .   : milestone, 67,

    section CallTarget+Inlining+NGEN
    This PR (4835) - mean (1,029ms)  : 1008, 1049
     .   : milestone, 1029,
    master - mean (1,028ms)  : 1009, 1047
     .   : milestone, 1028,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4835) - mean (106ms)  : 102, 109
     .   : milestone, 106,
    master - mean (106ms)  : 103, 108
     .   : milestone, 106,

    section CallTarget+Inlining+NGEN
    This PR (4835) - mean (730ms)  : 715, 746
     .   : milestone, 730,
    master - mean (730ms)  : 714, 746
     .   : milestone, 730,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4835) - mean (90ms)  : 87, 93
     .   : milestone, 90,
    master - mean (89ms)  : 87, 91
     .   : milestone, 89,

    section CallTarget+Inlining+NGEN
    This PR (4835) - mean (695ms)  : 673, 717
     .   : milestone, 695,
    master - mean (689ms)  : 665, 713
     .   : milestone, 689,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4835) - mean (188ms)  : 185, 190
     .   : milestone, 188,
    master - mean (188ms)  : 185, 192
     .   : milestone, 188,

    section CallTarget+Inlining+NGEN
    This PR (4835) - mean (1,138ms)  : 1117, 1158
     .   : milestone, 1138,
    master - mean (1,130ms)  : 1106, 1154
     .   : milestone, 1130,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4835) - mean (272ms)  : 268, 277
     .   : milestone, 272,
    master - mean (270ms)  : 266, 275
     .   : milestone, 270,

    section CallTarget+Inlining+NGEN
    This PR (4835) - mean (1,091ms)  : 1069, 1112
     .   : milestone, 1091,
    master - mean (1,083ms)  : 1056, 1111
     .   : milestone, 1083,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4835) - mean (262ms)  : 258, 265
     .   : milestone, 262,
    master - mean (261ms)  : 257, 265
     .   : milestone, 261,

    section CallTarget+Inlining+NGEN
    This PR (4835) - mean (1,052ms)  : 1034, 1070
     .   : milestone, 1052,
    master - mean (1,052ms)  : 1027, 1076
     .   : milestone, 1052,
Loading

@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs branch from bdd334c to 68ef01c Compare November 8, 2023 16:02
@andrewlock andrewlock requested a review from a team as a code owner November 8, 2023 16:02
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 25a8246 to 9ea6960 Compare November 8, 2023 16:02
@andrewlock andrewlock mentioned this pull request Nov 8, 2023
Closed
@andrewlock
Copy link
Member Author

andrewlock commented Nov 9, 2023 •
edited
Loading

Benchmarks Report 🐌

Benchmarks for #4835 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.167
  • 1 benchmarks are slower, with geometric mean 1.184
  • All benchmarks have the same allocations

The following thresholds were used for comparing the benchmark speeds:

  • Mann–Whitney U test with statistical test for significance of 5%
  • Only results indicating a difference greater than 10% and 0.3 ns are considered.

Allocation changes below 0.5% are ignored.

Benchmark details

Benchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartStopWithChild net6.0 8.14μs 42.1ns 202ns 0.0197 0.0079 0 7.29 KB
master StartStopWithChild netcoreapp3.1 10.3μs 56.9ns 341ns 0.0312 0.0156 0.0052 7.38 KB
master StartStopWithChild net472 15.7μs 51ns 197ns 1.28 0.311 0.0934 7.66 KB
#4835 StartStopWithChild net6.0 8.26μs 46.3ns 300ns 0.0241 0.0121 0.00402 7.29 KB
#4835 StartStopWithChild netcoreapp3.1 9.89μs 52.6ns 278ns 0.0256 0.0103 0 7.39 KB
#4835 StartStopWithChild net472 15.8μs 61ns 236ns 1.27 0.304 0.0881 7.66 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 497μs 243ns 940ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 644μs 289ns 1.12μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 802μs 562ns 2.18μs 0.398 0 0 3.3 KB
#4835 WriteAndFlushEnrichedTraces net6.0 496μs 556ns 2.15μs 0 0 0 2.7 KB
#4835 WriteAndFlushEnrichedTraces netcoreapp3.1 648μs 174ns 652ns 0 0 0 2.7 KB
#4835 WriteAndFlushEnrichedTraces net472 807μs 449ns 1.74μs 0.403 0 0 3.3 KB
Benchmarks.Trace.Asm.AppSecBodyBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #4835

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorMoreComplexBody‑netcoreapp3.1 1.167 4,276.37 3,664.33

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master AllCycleSimpleBody net6.0 44.3μs 78.3ns 303ns 0.0221 0 0 2.02 KB
master AllCycleSimpleBody netcoreapp3.1 45.5μs 185ns 715ns 0.0229 0 0 2 KB
master AllCycleSimpleBody net472 46.3μs 24.7ns 85.5ns 0.326 0 0 2.07 KB
master AllCycleMoreComplexBody net6.0 206μs 71.1ns 276ns 0.103 0 0 8.37 KB
master AllCycleMoreComplexBody netcoreapp3.1 210μs 83.6ns 324ns 0.105 0 0 8.26 KB
master AllCycleMoreComplexBody net472 217μs 85.3ns 319ns 1.28 0 0 8.43 KB
master ObjectExtractorSimpleBody net6.0 131ns 0.105ns 0.392ns 0.00393 0 0 280 B
master ObjectExtractorSimpleBody netcoreapp3.1 211ns 0.364ns 1.36ns 0.00376 0 0 272 B
master ObjectExtractorSimpleBody net472 159ns 0.103ns 0.397ns 0.0446 0 0 281 B
master ObjectExtractorMoreComplexBody net6.0 2.76μs 1.35ns 5.22ns 0.0527 0 0 3.78 KB
master ObjectExtractorMoreComplexBody netcoreapp3.1 4.28μs 1.45ns 5.62ns 0.0492 0 0 3.69 KB
master ObjectExtractorMoreComplexBody net472 3.5μs 2.75ns 10.3ns 0.602 0.00525 0 3.8 KB
#4835 AllCycleSimpleBody net6.0 42.9μs 76.2ns 295ns 0.0214 0 0 2.02 KB
#4835 AllCycleSimpleBody netcoreapp3.1 45.1μs 117ns 454ns 0.0221 0 0 2 KB
#4835 AllCycleSimpleBody net472 47μs 18ns 67.5ns 0.321 0 0 2.07 KB
#4835 AllCycleMoreComplexBody net6.0 204μs 77.8ns 301ns 0.102 0 0 8.37 KB
#4835 AllCycleMoreComplexBody netcoreapp3.1 207μs 102ns 380ns 0.103 0 0 8.26 KB
#4835 AllCycleMoreComplexBody net472 212μs 176ns 681ns 1.26 0 0 8.43 KB
#4835 ObjectExtractorSimpleBody net6.0 136ns 0.0508ns 0.19ns 0.00393 0 0 280 B
#4835 ObjectExtractorSimpleBody netcoreapp3.1 192ns 0.121ns 0.469ns 0.00367 0 0 272 B
#4835 ObjectExtractorSimpleBody net472 157ns 0.102ns 0.395ns 0.0446 0 0 281 B
#4835 ObjectExtractorMoreComplexBody net6.0 2.79μs 2.02ns 7.82ns 0.0529 0 0 3.78 KB
#4835 ObjectExtractorMoreComplexBody netcoreapp3.1 3.67μs 2.22ns 8.59ns 0.0496 0 0 3.69 KB
#4835 ObjectExtractorMoreComplexBody net472 3.46μs 2.11ns 7.88ns 0.603 0.0052 0 3.8 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 RunWaf(args=NestedMap (10)) net6.0 12.9μs 3.31ns 12.8ns 0.129 0 0 9.42 KB
master RunWaf(args=NestedMap (10)) netcoreapp3.1 20.4μs 48.2ns 174ns 0.122 0 0 9.41 KB
master RunWaf(args=NestedMap (10)) net472 29.9μs 8.65ns 33.5ns 1.49 0.0149 0 9.47 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 76.5μs 32.9ns 123ns 0.195 0 0 15.76 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 86.4μs 174ns 673ns 0.218 0 0 15.71 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net472 101μs 92.7ns 359ns 2.51 0 0 16.03 KB
master RunWaf(args=NestedMap (100)) net6.0 24.4μs 10.3ns 38.4ns 0.27 0 0 19.66 KB
master RunWaf(args=NestedMap (100)) netcoreapp3.1 39μs 13.8ns 53.5ns 0.273 0 0 20.41 KB
master RunWaf(args=NestedMap (100)) net472 58.3μs 26.1ns 101ns 3.26 0.0583 0 20.62 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) net6.0 91.4μs 35ns 121ns 0.363 0 0 26 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) netcoreapp3.1 111μs 81.6ns 316ns 0.334 0 0 26.71 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) net472 130μs 233ns 902ns 4.27 0.0648 0 27.18 KB
master RunWaf(args=NestedMap (20)) net6.0 24μs 23.9ns 92.5ns 0.276 0 0 19.39 KB
master RunWaf(args=NestedMap (20)) netcoreapp3.1 38.9μs 11.7ns 42.3ns 0.253 0 0 19.83 KB
master RunWaf(args=NestedMap (20)) net472 56.6μs 29.2ns 113ns 3.17 0.0566 0 20.03 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 92.6μs 36.8ns 138ns 0.369 0 0 25.74 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 110μs 37.5ns 130ns 0.328 0 0 26.14 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net472 132μs 152ns 589ns 4.18 0.0654 0 26.59 KB
#4835 RunWaf(args=NestedMap (10)) net6.0 13μs 3.44ns 12.9ns 0.132 0 0 9.42 KB
#4835 RunWaf(args=NestedMap (10)) netcoreapp3.1 19.9μs 5.85ns 21.9ns 0.119 0 0 9.41 KB
#4835 RunWaf(args=NestedMap (10)) net472 30.5μs 12.9ns 50ns 1.49 0 0 9.47 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 76.3μs 286ns 1.31μs 0.229 0 0 15.76 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 85.9μs 63.3ns 245ns 0.214 0 0 15.71 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [22]) net472 101μs 228ns 883ns 2.54 0 0 16.03 KB
#4835 RunWaf(args=NestedMap (100)) net6.0 24.4μs 5.53ns 20.7ns 0.271 0 0 19.66 KB
#4835 RunWaf(args=NestedMap (100)) netcoreapp3.1 39.4μs 22ns 82.1ns 0.275 0 0 20.41 KB
#4835 RunWaf(args=NestedMap (100)) net472 57.5μs 20.3ns 78.8ns 3.28 0.0575 0 20.62 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [23]) net6.0 90.8μs 40.7ns 158ns 0.367 0 0 26 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [23]) netcoreapp3.1 111μs 98.2ns 380ns 0.333 0 0 26.71 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [23]) net472 134μs 105ns 408ns 4.29 0.067 0 27.18 KB
#4835 RunWaf(args=NestedMap (20)) net6.0 24μs 4.07ns 14.1ns 0.265 0 0 19.39 KB
#4835 RunWaf(args=NestedMap (20)) netcoreapp3.1 39.3μs 13.1ns 50.7ns 0.255 0 0 19.83 KB
#4835 RunWaf(args=NestedMap (20)) net472 57.4μs 38.1ns 142ns 3.18 0.0577 0 20.03 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 91μs 36.1ns 140ns 0.321 0 0 25.74 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 109μs 244ns 911ns 0.33 0 0 26.14 KB
#4835 RunWafWithAttack(args=Neste(...)tack) [22]) net472 132μs 144ns 559ns 4.19 0.0655 0 26.59 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 171μs 173ns 672ns 0.17 0 0 18.04 KB
master SendRequest netcoreapp3.1 189μs 290ns 1.12μs 0.186 0 0 20.2 KB
master SendRequest net472 0.000213ns 0.000155ns 0.000602ns 0 0 0 0 b
#4835 SendRequest net6.0 172μs 117ns 455ns 0.172 0 0 18.04 KB
#4835 SendRequest netcoreapp3.1 191μs 331ns 1.28μs 0.193 0 0 20.2 KB
#4835 SendRequest net472 0.000399ns 0.000246ns 0.000954ns 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 534μs 628ns 2.26μs 0.566 0 0 41.46 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 651μs 1.14μs 4.43μs 0.327 0 0 41.63 KB
master WriteAndFlushEnrichedTraces net472 838μs 2.54μs 9.85μs 8.17 2.45 0.408 53.24 KB
#4835 WriteAndFlushEnrichedTraces net6.0 560μs 1.44μs 5.58μs 0.553 0 0 41.44 KB
#4835 WriteAndFlushEnrichedTraces netcoreapp3.1 657μs 484ns 1.68μs 0.331 0 0 41.7 KB
#4835 WriteAndFlushEnrichedTraces net472 864μs 3.99μs 15.5μs 8.08 2.55 0.425 53.23 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 956ns 0.872ns 3.38ns 0.0107 0 0 768 B
master ExecuteNonQuery netcoreapp3.1 1.3μs 0.476ns 1.78ns 0.0102 0 0 768 B
master ExecuteNonQuery net472 1.66μs 4.23ns 16.4ns 0.116 0 0 730 B
#4835 ExecuteNonQuery net6.0 1.01μs 0.914ns 3.54ns 0.0105 0 0 768 B
#4835 ExecuteNonQuery netcoreapp3.1 1.25μs 0.98ns 3.79ns 0.0101 0 0 768 B
#4835 ExecuteNonQuery net472 1.68μs 0.435ns 1.63ns 0.116 0 0 730 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.17μs 0.688ns 2.66ns 0.0128 0 0 936 B
master CallElasticsearch netcoreapp3.1 1.39μs 0.813ns 2.93ns 0.0125 0 0 936 B
master CallElasticsearch net472 2.32μs 0.682ns 2.64ns 0.151 0 0 955 B
master CallElasticsearchAsync net6.0 1.14μs 0.379ns 1.47ns 0.0127 0 0 912 B
master CallElasticsearchAsync netcoreapp3.1 1.51μs 1.81ns 7ns 0.0134 0 0 984 B
master CallElasticsearchAsync net472 2.46μs 1.62ns 6.26ns 0.16 0 0 1.01 KB
#4835 CallElasticsearch net6.0 1.09μs 0.611ns 2.37ns 0.0131 0 0 936 B
#4835 CallElasticsearch netcoreapp3.1 1.37μs 0.679ns 2.54ns 0.0123 0 0 936 B
#4835 CallElasticsearch net472 2.32μs 0.655ns 2.54ns 0.152 0 0 955 B
#4835 CallElasticsearchAsync net6.0 1.2μs 0.685ns 2.65ns 0.0126 0 0 912 B
#4835 CallElasticsearchAsync netcoreapp3.1 1.43μs 1.23ns 4.6ns 0.0136 0 0 984 B
#4835 CallElasticsearchAsync net472 2.5μs 1.52ns 5.26ns 0.16 0 0 1.01 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.31μs 0.572ns 2.14ns 0.0125 0 0 912 B
master ExecuteAsync netcoreapp3.1 1.52μs 0.472ns 1.77ns 0.0121 0 0 912 B
master ExecuteAsync net472 1.74μs 0.833ns 3.23ns 0.138 0 0 875 B
#4835 ExecuteAsync net6.0 1.23μs 0.935ns 3.5ns 0.013 0 0 912 B
#4835 ExecuteAsync netcoreapp3.1 1.48μs 0.681ns 2.55ns 0.0118 0 0 912 B
#4835 ExecuteAsync net472 1.64μs 0.942ns 3.65ns 0.139 0 0 875 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 3.8μs 1.3ns 5.04ns 0.0265 0 0 1.9 KB
master SendAsync netcoreapp3.1 4.61μs 1.8ns 6.99ns 0.0323 0 0 2.43 KB
master SendAsync net472 7.05μs 3.77ns 14.6ns 0.474 0 0 2.99 KB
#4835 SendAsync net6.0 3.77μs 0.945ns 3.41ns 0.0265 0 0 1.9 KB
#4835 SendAsync netcoreapp3.1 4.49μs 1.93ns 7.47ns 0.0314 0 0 2.43 KB
#4835 SendAsync net472 7.12μs 2.01ns 7.26ns 0.476 0 0 2.99 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.34μs 0.635ns 2.46ns 0.0221 0 0 1.57 KB
master EnrichedLog netcoreapp3.1 2.08μs 1.27ns 4.92ns 0.0208 0 0 1.57 KB
master EnrichedLog net472 2.34μs 3.15ns 12.2ns 0.236 0 0 1.49 KB
#4835 EnrichedLog net6.0 1.4μs 1.01ns 3.77ns 0.0223 0 0 1.57 KB
#4835 EnrichedLog netcoreapp3.1 2.01μs 0.659ns 2.28ns 0.0205 0 0 1.57 KB
#4835 EnrichedLog net472 2.29μs 3.85ns 14.4ns 0.236 0 0 1.49 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 111μs 90.3ns 350ns 0.0553 0 0 4.21 KB
master EnrichedLog netcoreapp3.1 119μs 195ns 754ns 0.0588 0 0 4.21 KB
master EnrichedLog net472 146μs 78ns 281ns 0.655 0.218 0 4.38 KB
#4835 EnrichedLog net6.0 114μs 206ns 798ns 0.0568 0 0 4.21 KB
#4835 EnrichedLog netcoreapp3.1 117μs 75.9ns 284ns 0.0584 0 0 4.21 KB
#4835 EnrichedLog net472 147μs 95.3ns 369ns 0.661 0.22 0 4.38 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 2.95μs 1.05ns 4.08ns 0.0297 0 0 2.13 KB
master EnrichedLog netcoreapp3.1 3.96μs 1.54ns 5.98ns 0.0277 0 0 2.13 KB
master EnrichedLog net472 4.53μs 3.6ns 13.9ns 0.305 0 0 1.93 KB
#4835 EnrichedLog net6.0 2.91μs 0.728ns 2.82ns 0.029 0 0 2.13 KB
#4835 EnrichedLog netcoreapp3.1 3.82μs 1.6ns 5.77ns 0.0287 0 0 2.13 KB
#4835 EnrichedLog net472 4.5μs 1.57ns 6.09ns 0.307 0 0 1.93 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.29μs 0.633ns 2.28ns 0.0154 0 0 1.1 KB
master SendReceive netcoreapp3.1 1.55μs 0.592ns 2.21ns 0.0148 0 0 1.1 KB
master SendReceive net472 1.95μs 1.16ns 4.33ns 0.176 0 0 1.12 KB
#4835 SendReceive net6.0 1.33μs 0.493ns 1.91ns 0.0153 0 0 1.1 KB
#4835 SendReceive netcoreapp3.1 1.52μs 1.12ns 4.32ns 0.0151 0 0 1.1 KB
#4835 SendReceive net472 2.06μs 1.55ns 6.01ns 0.176 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.62μs 1.08ns 4.2ns 0.021 0 0 1.53 KB
master EnrichedLog netcoreapp3.1 3.6μs 1.39ns 5.4ns 0.0197 0 0 1.58 KB
master EnrichedLog net472 3.97μs 1.7ns 6.37ns 0.309 0 0 1.96 KB
#4835 EnrichedLog net6.0 2.72μs 0.642ns 2.49ns 0.0217 0 0 1.53 KB
#4835 EnrichedLog netcoreapp3.1 3.39μs 0.725ns 2.71ns 0.0203 0 0 1.58 KB
#4835 EnrichedLog net472 4.07μs 2.14ns 8.3ns 0.309 0 0 1.96 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #4835

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.184 395.77 468.67

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 396ns 0.157ns 0.587ns 0.00743 0 0 536 B
master StartFinishSpan netcoreapp3.1 586ns 0.257ns 0.995ns 0.00731 0 0 536 B
master StartFinishSpan net472 673ns 0.211ns 0.817ns 0.0854 0 0 538 B
master StartFinishScope net6.0 526ns 0.185ns 0.715ns 0.00919 0 0 656 B
master StartFinishScope netcoreapp3.1 673ns 0.271ns 1.05ns 0.00893 0 0 656 B
master StartFinishScope net472 879ns 0.407ns 1.58ns 0.0981 0 0 618 B
#4835 StartFinishSpan net6.0 469ns 0.138ns 0.534ns 0.00754 0 0 536 B
#4835 StartFinishSpan netcoreapp3.1 566ns 0.277ns 0.959ns 0.0072 0 0 536 B
#4835 StartFinishSpan net472 639ns 0.167ns 0.626ns 0.0852 0 0 538 B
#4835 StartFinishScope net6.0 510ns 0.119ns 0.444ns 0.00917 0 0 656 B
#4835 StartFinishScope netcoreapp3.1 737ns 0.68ns 2.54ns 0.00875 0 0 656 B
#4835 StartFinishScope net472 829ns 0.561ns 2.17ns 0.0979 0 0 618 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 560ns 0.306ns 1.19ns 0.00913 0 0 656 B
master RunOnMethodBegin netcoreapp3.1 715ns 0.199ns 0.771ns 0.0088 0 0 656 B
master RunOnMethodBegin net472 953ns 0.487ns 1.82ns 0.0977 0 0 618 B
#4835 RunOnMethodBegin net6.0 618ns 0.252ns 0.976ns 0.00899 0 0 656 B
#4835 RunOnMethodBegin netcoreapp3.1 794ns 1.6ns 6.18ns 0.00909 0 0 656 B
#4835 RunOnMethodBegin net472 1.05μs 0.661ns 2.56ns 0.0981 0 0 618 B

@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs branch from 68ef01c to 4c982e2 Compare November 9, 2023 11:52
@andrewlock andrewlock requested a review from a team as a code owner November 9, 2023 11:52
@andrewlock andrewlock requested a review from a team November 9, 2023 11:52
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 9ea6960 to a18e08b Compare November 9, 2023 11:52
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs branch from 4c982e2 to e4d21ed Compare November 9, 2023 11:56
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from a18e08b to f6c6ab9 Compare November 10, 2023 13:51
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from f6c6ab9 to 99ec04b Compare November 10, 2023 13:56
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 99ec04b to 29c8cda Compare November 10, 2023 16:09
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 29c8cda to f07cb66 Compare November 10, 2023 16:17
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from f07cb66 to 0072c39 Compare November 13, 2023 11:44
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 0072c39 to 3f0a224 Compare November 13, 2023 14:42
@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 3f0a224 to 2d0b9c6 Compare November 14, 2023 12:58
@andrewlock
Copy link
Member Author

andrewlock commented Nov 14, 2023 •
edited
Loading

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 (4835) (11.425M)   : 0, 11424916
    master (11.393M)   : 0, 11393017
    benchmarks/2.9.0 (10.970M)   : 0, 10969859

    section Automatic
    This PR (4835) (7.866M)   : 0, 7865771
    master (8.127M)   : 0, 8126671
    benchmarks/2.9.0 (8.073M)   : 0, 8073230

    section Trace stats
    This PR (4835) (8.120M)   : 0, 8119854
    master (8.383M)   : 0, 8383234

    section Manual
    This PR (4835) (10.067M)   : 0, 10067196
    master (10.124M)   : 0, 10124331

    section Manual + Automatic
    This PR (4835) (7.432M)   : 0, 7432422
    master (7.429M)   : 0, 7428741

    section Version Conflict
    This PR (4835) (6.862M)   : 0, 6861928
    master (6.868M)   : 0, 6867861
Loading 
gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4835) (9.441M)   : 0, 9441364
    master (9.703M)   : 0, 9703335
    benchmarks/2.9.0 (9.427M)   : 0, 9427218

    section Automatic
    This PR (4835) (6.679M)   : 0, 6679469
    master (6.712M)   : 0, 6712306

    section Trace stats
    This PR (4835) (6.955M)   : 0, 6954569
    master (7.066M)   : 0, 7065575

    section Manual
    This PR (4835) (8.412M)   : 0, 8411777
    master (8.329M)   : 0, 8329299

    section Manual + Automatic
    This PR (4835) (6.331M)   : 0, 6330929
    master (6.412M)   : 0, 6412312

    section Version Conflict
    This PR (4835) (5.956M)   : 0, 5956363
    master (5.897M)   : 0, 5897282
Loading 
gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4835) (9.762M)   : 0, 9762131
    master (9.613M)   : 0, 9612719
    benchmarks/2.9.0 (9.396M)   : 0, 9396307

    section Automatic
    This PR (4835) (7.098M)   : 0, 7098316
    master (7.142M)   : 0, 7142467
    benchmarks/2.9.0 (7.124M)   : 0, 7124234

    section Trace stats
    This PR (4835) (7.263M)   : 0, 7262976
    master (7.161M)   : 0, 7161340

    section Manual
    This PR (4835) (8.526M)   : 0, 8525783
    master (8.954M)   : 0, 8954395

    section Manual + Automatic
    This PR (4835) (6.805M)   : 0, 6805356
    master (6.853M)   : 0, 6852829

    section Version Conflict
    This PR (4835) (6.059M)   : crit ,0, 6058952
    master (6.511M)   : 0, 6511482
Loading 
gantt
    title Throughput Linux x64 (ASM) (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    master (7.751M)   : 0, 7750725
    benchmarks/2.9.0 (7.730M)   : 0, 7730009

    section No attack
    master (2.219M)   : 0, 2219432
    benchmarks/2.9.0 (3.215M)   : 0, 3215012

    section Attack
    master (1.732M)   : 0, 1732028
    benchmarks/2.9.0 (2.455M)   : 0, 2455194

    section Blocking
    master (3.572M)   : 0, 3572443

    section IAST default
    master (6.701M)   : 0, 6700552

    section IAST full
    master (5.954M)   : 0, 5953584

    section Base vuln
    master (0.967M)   : 0, 966670

    section IAST vuln
    master (0.874M)   : 0, 873902
Loading

@andrewlock andrewlock force-pushed the andrew/telemetry/redacted-logs-3 branch from 2d0b9c6 to 7c33e85 Compare November 15, 2023 07:49
Base automatically changed from andrew/telemetry/redacted-logs-3 to master November 15, 2023 11:10
robertpi
robertpi approved these changes Nov 15, 2023
View reviewed changes
Copy link
Member

@robertpi robertpi left a comment

Choose a reason for hiding this comment

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

I confirm this will not negatively impact ASM :)

@andrewlock andrewlock merged commit 3de486b into master Nov 15, 2023
52 of 54 checks passed
@andrewlock andrewlock deleted the andrew/telemetry/redacted-logs branch November 15, 2023 15:03
@github-actions github-actions bot added this to the vNext milestone Nov 15, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@NachoEchevarria NachoEchevarria NachoEchevarria approved these changes

@pierotibou pierotibou pierotibou approved these changes

@robertpi robertpi robertpi approved these changes

Assignees
No one assigned
Labels
area:telemetry
Projects
None yet
Milestone
2.42.0
Development

Successfully merging this pull request may close these issues.
4 participants
@andrewlock @robertpi @pierotibou @NachoEchevarria