-
Notifications
You must be signed in to change notification settings - Fork 151
[R&D Week Profiling] Add tests for sync over async scenarios #6763
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.
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
Conversation
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:
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 (6763) - mean (69ms) : 67, 72
. : milestone, 69,
master - mean (70ms) : 67, 74
. : milestone, 70,
section CallTarget+Inlining+NGEN
This PR (6763) - mean (1,008ms) : 980, 1035
. : milestone, 1008,
master - mean (1,006ms) : 982, 1031
. : milestone, 1006,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6763) - mean (103ms) : 101, 105
. : milestone, 103,
master - mean (103ms) : 100, 105
. : milestone, 103,
section CallTarget+Inlining+NGEN
This PR (6763) - mean (691ms) : 670, 711
. : milestone, 691,
master - mean (689ms) : 674, 705
. : milestone, 689,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6763) - mean (90ms) : 88, 92
. : milestone, 90,
master - mean (90ms) : 87, 93
. : milestone, 90,
section CallTarget+Inlining+NGEN
This PR (6763) - mean (645ms) : 628, 661
. : milestone, 645,
master - mean (647ms) : 631, 664
. : milestone, 647,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6763) - mean (190ms) : 187, 194
. : milestone, 190,
master - mean (190ms) : 186, 193
. : milestone, 190,
section CallTarget+Inlining+NGEN
This PR (6763) - mean (1,109ms) : 1085, 1133
. : milestone, 1109,
master - mean (1,106ms) : 1071, 1140
. : milestone, 1106,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6763) - mean (269ms) : 263, 275
. : milestone, 269,
master - mean (269ms) : 265, 272
. : milestone, 269,
section CallTarget+Inlining+NGEN
This PR (6763) - mean (876ms) : 841, 911
. : milestone, 876,
master - mean (872ms) : 842, 903
. : milestone, 872,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6763) - mean (262ms) : 258, 265
. : milestone, 262,
master - mean (262ms) : 258, 266
. : milestone, 262,
section CallTarget+Inlining+NGEN
This PR (6763) - mean (857ms) : 820, 894
. : milestone, 857,
master - mean (859ms) : 826, 892
. : milestone, 859,
|
Datadog ReportAll test runs ✅ 2 Total Test Services: 0 Failed, 2 Passed Test Services
⌛ Performance Regressions vs Default Branch (5)
|
Benchmarks Report for tracer 🐌Benchmarks for #6763 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Fewer allocations 🎉
|
| Benchmark | Base Allocated | Diff Allocated | Change | Change % |
|---|---|---|---|---|
| Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark.WriteAndFlushEnrichedTraces‑netcoreapp3.1 | 41.82 KB | 41.55 KB | -272 B | -0.65% |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | WriteAndFlushEnrichedTraces |
net6.0 | 594μs | 4.36μs | 43.2μs | 0.571 | 0 | 0 | 41.52 KB |
| master | WriteAndFlushEnrichedTraces |
netcoreapp3.1 | 728μs | 4.21μs | 41.3μs | 0.361 | 0 | 0 | 41.82 KB |
| master | WriteAndFlushEnrichedTraces |
net472 | 851μs | 3.79μs | 16.9μs | 8.33 | 2.5 | 0.417 | 53.27 KB |
| #6763 | WriteAndFlushEnrichedTraces |
net6.0 | 624μs | 3.77μs | 37.3μs | 0.573 | 0 | 0 | 41.67 KB |
| #6763 | WriteAndFlushEnrichedTraces |
netcoreapp3.1 | 751μs | 4.86μs | 47.8μs | 0.353 | 0 | 0 | 41.55 KB |
| #6763 | WriteAndFlushEnrichedTraces |
net472 | 857μs | 4.32μs | 19.8μs | 8.74 | 2.62 | 0.437 | 53.33 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.36μs | 0.861ns | 3.22ns | 0.0142 | 0 | 0 | 1.02 KB |
| master | ExecuteNonQuery |
netcoreapp3.1 | 1.77μs | 1.27ns | 4.93ns | 0.0132 | 0 | 0 | 1.02 KB |
| master | ExecuteNonQuery |
net472 | 1.98μs | 2.51ns | 9.38ns | 0.156 | 0.00099 | 0 | 987 B |
| #6763 | ExecuteNonQuery |
net6.0 | 1.45μs | 2.02ns | 7.83ns | 0.0144 | 0 | 0 | 1.02 KB |
| #6763 | ExecuteNonQuery |
netcoreapp3.1 | 1.86μs | 2.88ns | 11.1ns | 0.0139 | 0 | 0 | 1.02 KB |
| #6763 | ExecuteNonQuery |
net472 | 2.1μs | 3.21ns | 12.5ns | 0.156 | 0.00103 | 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.29μs | 1.28ns | 4.97ns | 0.0135 | 0 | 0 | 976 B |
| master | CallElasticsearch |
netcoreapp3.1 | 1.58μs | 0.509ns | 1.91ns | 0.0133 | 0 | 0 | 976 B |
| master | CallElasticsearch |
net472 | 2.59μs | 1.77ns | 6.86ns | 0.158 | 0 | 0 | 995 B |
| master | CallElasticsearchAsync |
net6.0 | 1.21μs | 0.764ns | 2.96ns | 0.0133 | 0 | 0 | 952 B |
| master | CallElasticsearchAsync |
netcoreapp3.1 | 1.67μs | 0.517ns | 1.79ns | 0.0134 | 0 | 0 | 1.02 KB |
| master | CallElasticsearchAsync |
net472 | 2.73μs | 0.688ns | 2.48ns | 0.167 | 0 | 0 | 1.05 KB |
| #6763 | CallElasticsearch |
net6.0 | 1.21μs | 0.531ns | 1.99ns | 0.014 | 0 | 0 | 976 B |
| #6763 | CallElasticsearch |
netcoreapp3.1 | 1.63μs | 0.64ns | 2.39ns | 0.013 | 0 | 0 | 976 B |
| #6763 | CallElasticsearch |
net472 | 2.7μs | 1.37ns | 5.3ns | 0.158 | 0 | 0 | 995 B |
| #6763 | CallElasticsearchAsync |
net6.0 | 1.29μs | 0.639ns | 2.39ns | 0.0135 | 0 | 0 | 952 B |
| #6763 | CallElasticsearchAsync |
netcoreapp3.1 | 1.63μs | 1.58ns | 5.92ns | 0.0138 | 0 | 0 | 1.02 KB |
| #6763 | CallElasticsearchAsync |
net472 | 2.81μs | 1.16ns | 4.47ns | 0.166 | 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.23μs | 0.553ns | 2.07ns | 0.013 | 0 | 0 | 952 B |
| master | ExecuteAsync |
netcoreapp3.1 | 1.59μs | 0.78ns | 2.92ns | 0.0128 | 0 | 0 | 952 B |
| master | ExecuteAsync |
net472 | 1.86μs | 3.18ns | 11.9ns | 0.145 | 0 | 0 | 915 B |
| #6763 | ExecuteAsync |
net6.0 | 1.33μs | 0.531ns | 1.99ns | 0.0133 | 0 | 0 | 952 B |
| #6763 | ExecuteAsync |
netcoreapp3.1 | 1.77μs | 0.723ns | 2.8ns | 0.0133 | 0 | 0 | 952 B |
| #6763 | ExecuteAsync |
net472 | 1.69μs | 0.439ns | 1.7ns | 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.34μs | 1.45ns | 5.03ns | 0.0326 | 0 | 0 | 2.31 KB |
| master | SendAsync |
netcoreapp3.1 | 5.25μs | 1.76ns | 6.59ns | 0.0394 | 0 | 0 | 2.85 KB |
| master | SendAsync |
net472 | 7.47μs | 2.52ns | 9.77ns | 0.493 | 0 | 0 | 3.12 KB |
| #6763 | SendAsync |
net6.0 | 4.37μs | 1.85ns | 6.91ns | 0.0308 | 0 | 0 | 2.31 KB |
| #6763 | SendAsync |
netcoreapp3.1 | 5.35μs | 2.98ns | 11.6ns | 0.0374 | 0 | 0 | 2.85 KB |
| #6763 | SendAsync |
net472 | 7.48μs | 2.66ns | 10.3ns | 0.494 | 0 | 0 | 3.12 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.52μs | 0.852ns | 3.3ns | 0.0239 | 0 | 0 | 1.69 KB |
| master | EnrichedLog |
netcoreapp3.1 | 2.19μs | 1.1ns | 3.97ns | 0.023 | 0 | 0 | 1.69 KB |
| master | EnrichedLog |
net472 | 2.61μs | 1.36ns | 5.27ns | 0.257 | 0 | 0 | 1.62 KB |
| #6763 | EnrichedLog |
net6.0 | 1.51μs | 0.966ns | 3.48ns | 0.0242 | 0 | 0 | 1.69 KB |
| #6763 | EnrichedLog |
netcoreapp3.1 | 2.23μs | 1.24ns | 4.63ns | 0.0224 | 0 | 0 | 1.69 KB |
| #6763 | EnrichedLog |
net472 | 2.67μs | 1.51ns | 5.67ns | 0.258 | 0 | 0 | 1.62 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 | 118ns | 455ns | 0.0562 | 0 | 0 | 4.3 KB |
| master | EnrichedLog |
netcoreapp3.1 | 117μs | 239ns | 926ns | 0.058 | 0 | 0 | 4.3 KB |
| master | EnrichedLog |
net472 | 151μs | 130ns | 505ns | 0.676 | 0.225 | 0 | 4.49 KB |
| #6763 | EnrichedLog |
net6.0 | 112μs | 171ns | 616ns | 0.0581 | 0 | 0 | 4.3 KB |
| #6763 | EnrichedLog |
netcoreapp3.1 | 117μs | 178ns | 689ns | 0.0582 | 0 | 0 | 4.3 KB |
| #6763 | EnrichedLog |
net472 | 150μs | 180ns | 699ns | 0.673 | 0.224 | 0 | 4.49 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.11μs | 1.22ns | 4.73ns | 0.0317 | 0 | 0 | 2.25 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4.17μs | 2.19ns | 8.18ns | 0.0292 | 0 | 0 | 2.25 KB |
| master | EnrichedLog |
net472 | 4.76μs | 2.03ns | 7.85ns | 0.329 | 0 | 0 | 2.07 KB |
| #6763 | EnrichedLog |
net6.0 | 3.13μs | 1.26ns | 4.7ns | 0.0312 | 0 | 0 | 2.25 KB |
| #6763 | EnrichedLog |
netcoreapp3.1 | 4.13μs | 1.66ns | 5.76ns | 0.029 | 0 | 0 | 2.25 KB |
| #6763 | EnrichedLog |
net472 | 4.86μs | 1.8ns | 6.97ns | 0.328 | 0 | 0 | 2.07 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.46μs | 1.63ns | 6.33ns | 0.016 | 0 | 0 | 1.14 KB |
| master | SendReceive |
netcoreapp3.1 | 1.78μs | 0.975ns | 3.77ns | 0.0152 | 0 | 0 | 1.14 KB |
| master | SendReceive |
net472 | 2.1μs | 1.4ns | 5.25ns | 0.183 | 0 | 0 | 1.16 KB |
| #6763 | SendReceive |
net6.0 | 1.34μs | 0.726ns | 2.72ns | 0.0161 | 0 | 0 | 1.14 KB |
| #6763 | SendReceive |
netcoreapp3.1 | 1.85μs | 2.05ns | 7.4ns | 0.0158 | 0 | 0 | 1.14 KB |
| #6763 | SendReceive |
net472 | 2.07μs | 0.776ns | 3.01ns | 0.183 | 0 | 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.75μs | 0.752ns | 2.91ns | 0.0221 | 0 | 0 | 1.62 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4μs | 1.28ns | 4.96ns | 0.0218 | 0 | 0 | 1.67 KB |
| master | EnrichedLog |
net472 | 4.58μs | 3.11ns | 11.6ns | 0.327 | 0 | 0 | 2.07 KB |
| #6763 | EnrichedLog |
net6.0 | 2.83μs | 1.17ns | 4.54ns | 0.0227 | 0 | 0 | 1.62 KB |
| #6763 | EnrichedLog |
netcoreapp3.1 | 4.02μs | 1.09ns | 4.22ns | 0.0221 | 0 | 0 | 1.67 KB |
| #6763 | EnrichedLog |
net472 | 4.63μs | 2.25ns | 8.71ns | 0.326 | 0 | 0 | 2.07 KB |
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️
Slower ⚠️ in #6763
Benchmark
diff/base
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0
1.208
472.02
570.04
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0
1.178
389.07
458.19
Faster 🎉 in #6763
Benchmark
base/diff
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1
1.138
782.60
687.47
| Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 | 1.208 | 472.02 | 570.04 | |
| Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 | 1.178 | 389.07 | 458.19 |
| Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1 | 1.138 | 782.60 | 687.47 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | StartFinishSpan |
net6.0 | 389ns | 0.13ns | 0.503ns | 0.008 | 0 | 0 | 576 B |
| master | StartFinishSpan |
netcoreapp3.1 | 638ns | 0.608ns | 2.36ns | 0.00796 | 0 | 0 | 576 B |
| master | StartFinishSpan |
net472 | 652ns | 0.305ns | 1.18ns | 0.0915 | 0 | 0 | 578 B |
| master | StartFinishScope |
net6.0 | 472ns | 0.0667ns | 0.25ns | 0.00967 | 0 | 0 | 696 B |
| master | StartFinishScope |
netcoreapp3.1 | 782ns | 0.243ns | 0.941ns | 0.00935 | 0 | 0 | 696 B |
| master | StartFinishScope |
net472 | 907ns | 1.27ns | 4.92ns | 0.104 | 0 | 0 | 658 B |
| #6763 | StartFinishSpan |
net6.0 | 458ns | 0.222ns | 0.86ns | 0.00797 | 0 | 0 | 576 B |
| #6763 | StartFinishSpan |
netcoreapp3.1 | 582ns | 0.567ns | 2.2ns | 0.00778 | 0 | 0 | 576 B |
| #6763 | StartFinishSpan |
net472 | 681ns | 0.319ns | 1.24ns | 0.0917 | 0 | 0 | 578 B |
| #6763 | StartFinishScope |
net6.0 | 570ns | 0.241ns | 0.932ns | 0.0097 | 0 | 0 | 696 B |
| #6763 | StartFinishScope |
netcoreapp3.1 | 688ns | 0.243ns | 0.943ns | 0.00965 | 0 | 0 | 696 B |
| #6763 | StartFinishScope |
net472 | 868ns | 1.51ns | 5.84ns | 0.104 | 0 | 0 | 658 B |
Benchmarks.Trace.TraceAnnotationsBenchmark - Slower ⚠️ Same allocations ✔️
Slower ⚠️ in #6763
Benchmark
diff/base
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0
1.197
635.64
760.65
| Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 | 1.197 | 635.64 | 760.65 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | RunOnMethodBegin |
net6.0 | 636ns | 0.397ns | 1.54ns | 0.00982 | 0 | 0 | 696 B |
| master | RunOnMethodBegin |
netcoreapp3.1 | 955ns | 0.349ns | 1.35ns | 0.0091 | 0 | 0 | 696 B |
| master | RunOnMethodBegin |
net472 | 1.1μs | 0.351ns | 1.36ns | 0.105 | 0 | 0 | 658 B |
| #6763 | RunOnMethodBegin |
net6.0 | 761ns | 0.212ns | 0.823ns | 0.00989 | 0 | 0 | 696 B |
| #6763 | RunOnMethodBegin |
netcoreapp3.1 | 998ns | 0.563ns | 2.18ns | 0.0092 | 0 | 0 | 696 B |
| #6763 | RunOnMethodBegin |
net472 | 1.19μs | 0.232ns | 0.868ns | 0.104 | 0 | 0 | 658 B |
gleocadie
left a comment
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LGTM
## Summary of changes
Add sync-over-async scenarios
## Reason for change
Investigate insights related to async anti-patterns
## Implementation details
Add scenarios for both .NET Framework and .NET Core
## Test coverage
## Other details
<!-- Fixes #{issue} -->
<!-- ⚠️ Note: where possible, please obtain 2 approvals prior to
merging. Unless CODEOWNERS specifies otherwise, for external teams it is
typically best to have one review from a team member, and one review
from apm-dotnet. Trivial changes do not require 2 reviews. -->
Summary of changes
Add sync-over-async scenarios
Reason for change
Investigate insights related to async anti-patterns
Implementation details
Add scenarios for both .NET Framework and .NET Core
Test coverage
Other details