-
Notifications
You must be signed in to change notification settings - Fork 143
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
[Profiler] Avoid ETW tests flackiness #6368
Conversation
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
Datadog ReportBranch report: ✅ 0 Failed, 451383 Passed, 3185 Skipped, 20h 57m 15.07s Total Time |
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 (6368) - mean (69ms) : 66, 72
. : milestone, 69,
master - mean (69ms) : 66, 71
. : milestone, 69,
section CallTarget+Inlining+NGEN
This PR (6368) - mean (979ms) : 961, 998
. : milestone, 979,
master - mean (976ms) : 944, 1008
. : milestone, 976,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6368) - mean (108ms) : 106, 110
. : milestone, 108,
master - mean (108ms) : 105, 110
. : milestone, 108,
section CallTarget+Inlining+NGEN
This PR (6368) - mean (679ms) : 664, 695
. : milestone, 679,
master - mean (672ms) : 657, 687
. : milestone, 672,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6368) - mean (91ms) : 89, 93
. : milestone, 91,
master - mean (91ms) : 90, 93
. : milestone, 91,
section CallTarget+Inlining+NGEN
This PR (6368) - mean (634ms) : 621, 646
. : milestone, 634,
master - mean (626ms) : 610, 641
. : milestone, 626,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6368) - mean (191ms) : 186, 196
. : milestone, 191,
master - mean (191ms) : 187, 195
. : milestone, 191,
section CallTarget+Inlining+NGEN
This PR (6368) - mean (1,096ms) : 1067, 1125
. : milestone, 1096,
master - mean (1,094ms) : 1063, 1125
. : milestone, 1094,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6368) - mean (277ms) : 272, 282
. : milestone, 277,
master - mean (277ms) : 272, 281
. : milestone, 277,
section CallTarget+Inlining+NGEN
This PR (6368) - mean (872ms) : 847, 896
. : milestone, 872,
master - mean (868ms) : 842, 895
. : milestone, 868,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6368) - mean (266ms) : 262, 271
. : milestone, 266,
master - mean (266ms) : 262, 270
. : milestone, 266,
section CallTarget+Inlining+NGEN
This PR (6368) - mean (855ms) : 826, 884
. : milestone, 855,
master - mean (847ms) : 812, 882
. : milestone, 847,
|
Benchmarks Report for tracer 🐌Benchmarks for #6368 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 ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Faster 🎉 Same allocations ✔️
|
Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net6.0 | 1.127 | 1,330.69 | 1,180.52 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | ExecuteAsync |
net6.0 | 1.33μs | 0.469ns | 1.82ns | 0.0133 | 0 | 0 | 952 B |
master | ExecuteAsync |
netcoreapp3.1 | 1.62μs | 0.654ns | 2.53ns | 0.0124 | 0 | 0 | 952 B |
master | ExecuteAsync |
net472 | 1.75μs | 0.873ns | 3.15ns | 0.145 | 0 | 0 | 915 B |
#6368 | ExecuteAsync |
net6.0 | 1.18μs | 0.346ns | 1.25ns | 0.0131 | 0 | 0 | 952 B |
#6368 | ExecuteAsync |
netcoreapp3.1 | 1.7μs | 0.923ns | 3.57ns | 0.0128 | 0 | 0 | 952 B |
#6368 | ExecuteAsync |
net472 | 1.79μs | 0.836ns | 3.24ns | 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.52μs | 3.22ns | 11.6ns | 0.0317 | 0 | 0 | 2.31 KB |
master | SendAsync |
netcoreapp3.1 | 5.23μs | 1.29ns | 5ns | 0.0366 | 0 | 0 | 2.85 KB |
master | SendAsync |
net472 | 7.33μs | 2.03ns | 7.88ns | 0.495 | 0 | 0 | 3.12 KB |
#6368 | SendAsync |
net6.0 | 4.44μs | 5.42ns | 21ns | 0.0314 | 0 | 0 | 2.31 KB |
#6368 | SendAsync |
netcoreapp3.1 | 5.34μs | 5.98ns | 23.2ns | 0.0371 | 0 | 0 | 2.85 KB |
#6368 | SendAsync |
net472 | 7.43μs | 0.966ns | 3.48ns | 0.494 | 0 | 0 | 3.12 KB |
Benchmarks.Trace.ILoggerBenchmark - Faster 🎉 Same allocations ✔️
Faster 🎉 in #6368
Benchmark
base/diff
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.ILoggerBenchmark.EnrichedLog‑net6.0
1.114
1,617.34
1,451.95
Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.ILoggerBenchmark.EnrichedLog‑net6.0 | 1.114 | 1,617.34 | 1,451.95 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | EnrichedLog |
net6.0 | 1.62μs | 0.908ns | 3.4ns | 0.0227 | 0 | 0 | 1.64 KB |
master | EnrichedLog |
netcoreapp3.1 | 2.13μs | 0.629ns | 2.44ns | 0.0224 | 0 | 0 | 1.64 KB |
master | EnrichedLog |
net472 | 2.71μs | 1.13ns | 4.38ns | 0.25 | 0 | 0 | 1.57 KB |
#6368 | EnrichedLog |
net6.0 | 1.45μs | 0.633ns | 2.45ns | 0.0226 | 0 | 0 | 1.64 KB |
#6368 | EnrichedLog |
netcoreapp3.1 | 2.1μs | 0.417ns | 1.56ns | 0.022 | 0 | 0 | 1.64 KB |
#6368 | EnrichedLog |
net472 | 2.73μs | 1.41ns | 5.28ns | 0.25 | 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 | 119μs | 119ns | 461ns | 0.0603 | 0 | 0 | 4.28 KB |
master | EnrichedLog |
netcoreapp3.1 | 124μs | 136ns | 526ns | 0 | 0 | 0 | 4.28 KB |
master | EnrichedLog |
net472 | 152μs | 152ns | 589ns | 0.69 | 0.23 | 0 | 4.46 KB |
#6368 | EnrichedLog |
net6.0 | 121μs | 140ns | 525ns | 0 | 0 | 0 | 4.28 KB |
#6368 | EnrichedLog |
netcoreapp3.1 | 124μs | 87ns | 337ns | 0 | 0 | 0 | 4.28 KB |
#6368 | EnrichedLog |
net472 | 153μs | 137ns | 529ns | 0.692 | 0.231 | 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.07μs | 0.84ns | 3.25ns | 0.0307 | 0 | 0 | 2.2 KB |
master | EnrichedLog |
netcoreapp3.1 | 4.08μs | 1.32ns | 5.09ns | 0.0285 | 0 | 0 | 2.2 KB |
master | EnrichedLog |
net472 | 4.96μs | 2.43ns | 9.41ns | 0.319 | 0 | 0 | 2.02 KB |
#6368 | EnrichedLog |
net6.0 | 2.99μs | 1.34ns | 5.2ns | 0.031 | 0 | 0 | 2.2 KB |
#6368 | EnrichedLog |
netcoreapp3.1 | 4.44μs | 6.41ns | 24.8ns | 0.0293 | 0 | 0 | 2.2 KB |
#6368 | EnrichedLog |
net472 | 4.85μs | 1ns | 3.87ns | 0.318 | 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.42μs | 0.336ns | 1.3ns | 0.0156 | 0 | 0 | 1.14 KB |
master | SendReceive |
netcoreapp3.1 | 1.72μs | 0.937ns | 3.51ns | 0.0155 | 0 | 0 | 1.14 KB |
master | SendReceive |
net472 | 2.12μs | 3.57ns | 13.8ns | 0.183 | 0 | 0 | 1.16 KB |
#6368 | SendReceive |
net6.0 | 1.34μs | 0.588ns | 2.28ns | 0.0161 | 0 | 0 | 1.14 KB |
#6368 | SendReceive |
netcoreapp3.1 | 1.76μs | 0.911ns | 3.41ns | 0.0149 | 0 | 0 | 1.14 KB |
#6368 | SendReceive |
net472 | 2.11μs | 1.53ns | 5.71ns | 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.62μs | 0.971ns | 3.76ns | 0.0224 | 0 | 0 | 1.6 KB |
master | EnrichedLog |
netcoreapp3.1 | 3.98μs | 2.35ns | 9.09ns | 0.0219 | 0 | 0 | 1.65 KB |
master | EnrichedLog |
net472 | 4.44μs | 3.15ns | 12.2ns | 0.323 | 0 | 0 | 2.04 KB |
#6368 | EnrichedLog |
net6.0 | 2.8μs | 1.56ns | 5.83ns | 0.0224 | 0 | 0 | 1.6 KB |
#6368 | EnrichedLog |
netcoreapp3.1 | 3.93μs | 1.66ns | 6.45ns | 0.0215 | 0 | 0 | 1.65 KB |
#6368 | EnrichedLog |
net472 | 4.35μs | 1.42ns | 5.3ns | 0.322 | 0 | 0 | 2.04 KB |
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | StartFinishSpan |
net6.0 | 396ns | 0.55ns | 2.13ns | 0.00802 | 0 | 0 | 576 B |
master | StartFinishSpan |
netcoreapp3.1 | 548ns | 0.95ns | 3.68ns | 0.00773 | 0 | 0 | 576 B |
master | StartFinishSpan |
net472 | 635ns | 1.04ns | 4.02ns | 0.0918 | 0 | 0 | 578 B |
master | StartFinishScope |
net6.0 | 518ns | 0.905ns | 3.51ns | 0.00966 | 0 | 0 | 696 B |
master | StartFinishScope |
netcoreapp3.1 | 700ns | 1.27ns | 4.91ns | 0.00944 | 0 | 0 | 696 B |
master | StartFinishScope |
net472 | 888ns | 1.31ns | 5.09ns | 0.104 | 0 | 0 | 658 B |
#6368 | StartFinishSpan |
net6.0 | 410ns | 0.528ns | 1.97ns | 0.00808 | 0 | 0 | 576 B |
#6368 | StartFinishSpan |
netcoreapp3.1 | 549ns | 0.707ns | 2.74ns | 0.00778 | 0 | 0 | 576 B |
#6368 | StartFinishSpan |
net472 | 679ns | 2.36ns | 9.14ns | 0.0917 | 0 | 0 | 578 B |
#6368 | StartFinishScope |
net6.0 | 497ns | 0.452ns | 1.63ns | 0.00974 | 0 | 0 | 696 B |
#6368 | StartFinishScope |
netcoreapp3.1 | 770ns | 1.11ns | 4.29ns | 0.0093 | 0 | 0 | 696 B |
#6368 | StartFinishScope |
net472 | 854ns | 2.22ns | 8.6ns | 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 | 656ns | 1.2ns | 4.65ns | 0.00954 | 0 | 0 | 696 B |
master | RunOnMethodBegin |
netcoreapp3.1 | 897ns | 3.82ns | 14.8ns | 0.00954 | 0 | 0 | 696 B |
master | RunOnMethodBegin |
net472 | 1.11μs | 2.31ns | 8.97ns | 0.104 | 0 | 0 | 658 B |
#6368 | RunOnMethodBegin |
net6.0 | 611ns | 1.07ns | 4.15ns | 0.00981 | 0 | 0 | 696 B |
#6368 | RunOnMethodBegin |
netcoreapp3.1 | 940ns | 1.76ns | 6.82ns | 0.0096 | 0 | 0 | 696 B |
#6368 | RunOnMethodBegin |
net472 | 1.06μs | 3.15ns | 12.2ns | 0.105 | 0 | 0 | 658 B |
Throughput/Crank Report ⚡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 (6368) (11.222M) : 0, 11222487
master (11.137M) : 0, 11136693
benchmarks/2.9.0 (11.033M) : 0, 11032866
section Automatic
This PR (6368) (7.355M) : 0, 7355497
master (7.208M) : 0, 7207773
benchmarks/2.9.0 (7.786M) : 0, 7785853
section Trace stats
master (7.606M) : 0, 7605597
section Manual
master (11.229M) : 0, 11228588
section Manual + Automatic
This PR (6368) (6.686M) : 0, 6686421
master (6.591M) : 0, 6590949
section DD_TRACE_ENABLED=0
master (10.370M) : 0, 10369998
gantt
title Throughput Linux arm64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6368) (9.495M) : 0, 9495423
master (9.315M) : 0, 9314649
benchmarks/2.9.0 (9.495M) : 0, 9494821
section Automatic
This PR (6368) (6.362M) : 0, 6362194
master (6.373M) : 0, 6372940
section Trace stats
master (6.614M) : 0, 6613938
section Manual
master (9.430M) : 0, 9429935
section Manual + Automatic
This PR (6368) (6.020M) : 0, 6019961
master (5.873M) : 0, 5872760
section DD_TRACE_ENABLED=0
master (8.828M) : 0, 8827967
gantt
title Throughput Windows x64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6368) (9.606M) : 0, 9606356
master (9.813M) : 0, 9813025
benchmarks/2.9.0 (10.020M) : 0, 10019592
section Automatic
This PR (6368) (6.165M) : crit ,0, 6164803
master (6.493M) : 0, 6493296
benchmarks/2.9.0 (7.255M) : 0, 7255257
section Trace stats
master (7.088M) : 0, 7087833
section Manual
master (10.002M) : 0, 10001889
section Manual + Automatic
This PR (6368) (5.906M) : 0, 5906376
master (6.146M) : 0, 6145502
section DD_TRACE_ENABLED=0
master (9.378M) : 0, 9377652
|
c17ea1c
to
55f4cfd
Compare
## Summary of changes Pick a less CPU intensive scenario and increase test timeout ## Reason for change The previous version of the tests showed that the agent proxy was not able to asynchronously send the recorded events before the test ends. ## Implementation details Increase the timeout so the profiled application lives long enough to receive the recorded events ## Test coverage yes ## 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
Pick a less CPU intensive scenario and increase test timeout
Reason for change
The previous version of the tests showed that the agent proxy was not able to asynchronously send the recorded events before the test ends.
Implementation details
Increase the timeout so the profiled application lives long enough to receive the recorded events
Test coverage
yes
Other details