[DSM] Switch from ManualResetEventSlim to AsyncManualResetEvent#6356
Conversation
| } | ||
|
|
||
| _processingMutex.Wait(); | ||
| await _processingMutex.WaitAsync().ConfigureAwait(false); |
There was a problem hiding this comment.
So just to clarify, we sit on the thread pool for this function (compared to SerializeTracesLoop) because we start this function with _processTask = Task.Run(ProcessQueueLoopAsync); where the other one we do a _serializationTask = automaticFlush ? Task.Factory.StartNew(SerializeTracesLoop, TaskCreationOptions.LongRunning)
Which gets it out of the thread pool.
Should we do the same for both and update that one to this as well?
There was a problem hiding this comment.
Should we do the same for both and update that one to this as well?
As I understand it, that wouldn't work here because we're using async/await. Using LongRunning makes sense for the non-async method, as it (potentially) stays out of the pool entirely, but when you use async/await you lose the benefit seeing as you're going to be resuming on different threads potentially anyway.
cc @kevingosse to sense check me 😄
Datadog ReportBranch report: ✅ 0 Failed, 448371 Passed, 2721 Skipped, 19h 16m 35.41s 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 (6356) - mean (76ms) : 72, 80
. : milestone, 76,
master - mean (69ms) : 67, 70
. : milestone, 69,
section CallTarget+Inlining+NGEN
This PR (6356) - mean (1,033ms) : crit, 1018, 1048
. : crit, milestone, 1033,
master - mean (975ms) : 954, 996
. : milestone, 975,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6356) - mean (119ms) : 113, 124
. : milestone, 119,
master - mean (108ms) : 105, 110
. : milestone, 108,
section CallTarget+Inlining+NGEN
This PR (6356) - mean (720ms) : crit, 708, 733
. : crit, milestone, 720,
master - mean (679ms) : 666, 691
. : milestone, 679,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6356) - mean (102ms) : 95, 108
. : milestone, 102,
master - mean (91ms) : 88, 94
. : milestone, 91,
section CallTarget+Inlining+NGEN
This PR (6356) - mean (673ms) : crit, 655, 692
. : crit, milestone, 673,
master - mean (630ms) : 615, 646
. : milestone, 630,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6356) - mean (191ms) : 186, 196
. : milestone, 191,
master - mean (190ms) : 186, 194
. : milestone, 190,
section CallTarget+Inlining+NGEN
This PR (6356) - mean (1,096ms) : 1070, 1122
. : milestone, 1096,
master - mean (1,094ms) : 1064, 1124
. : milestone, 1094,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6356) - mean (278ms) : 271, 284
. : milestone, 278,
master - mean (277ms) : 272, 282
. : milestone, 277,
section CallTarget+Inlining+NGEN
This PR (6356) - mean (870ms) : 842, 898
. : milestone, 870,
master - mean (871ms) : 837, 906
. : milestone, 871,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6356) - mean (267ms) : 262, 273
. : milestone, 267,
master - mean (266ms) : 261, 271
. : milestone, 266,
section CallTarget+Inlining+NGEN
This PR (6356) - mean (851ms) : 816, 886
. : milestone, 851,
master - mean (851ms) : 810, 893
. : milestone, 851,
|
ManualResetEventSlim to AsyncManualResetEvent
Benchmarks Report for tracer 🐌Benchmarks for #6356 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 - Faster 🎉 Same allocations ✔️
|
| Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync‑net6.0 | 1.121 | 1,399.23 | 1,248.56 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | CallElasticsearch |
net6.0 | 1.18μs | 0.683ns | 2.56ns | 0.0136 | 0 | 0 | 976 B |
| master | CallElasticsearch |
netcoreapp3.1 | 1.47μs | 0.638ns | 2.39ns | 0.0127 | 0 | 0 | 976 B |
| master | CallElasticsearch |
net472 | 2.5μs | 1.38ns | 5.14ns | 0.158 | 0 | 0 | 995 B |
| master | CallElasticsearchAsync |
net6.0 | 1.41μs | 4.89ns | 19ns | 0.0135 | 0 | 0 | 952 B |
| master | CallElasticsearchAsync |
netcoreapp3.1 | 1.75μs | 0.81ns | 2.92ns | 0.014 | 0 | 0 | 1.02 KB |
| master | CallElasticsearchAsync |
net472 | 2.7μs | 1.69ns | 6.32ns | 0.167 | 0 | 0 | 1.05 KB |
| #6356 | CallElasticsearch |
net6.0 | 1.17μs | 0.502ns | 1.94ns | 0.0134 | 0 | 0 | 976 B |
| #6356 | CallElasticsearch |
netcoreapp3.1 | 1.55μs | 0.654ns | 2.45ns | 0.013 | 0 | 0 | 976 B |
| #6356 | CallElasticsearch |
net472 | 2.6μs | 2.11ns | 8.16ns | 0.158 | 0 | 0 | 995 B |
| #6356 | CallElasticsearchAsync |
net6.0 | 1.25μs | 0.634ns | 2.37ns | 0.0131 | 0 | 0 | 952 B |
| #6356 | CallElasticsearchAsync |
netcoreapp3.1 | 1.64μs | 0.773ns | 3ns | 0.0139 | 0 | 0 | 1.02 KB |
| #6356 | CallElasticsearchAsync |
net472 | 2.58μs | 2.21ns | 8.57ns | 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.28μs | 0.408ns | 1.53ns | 0.0135 | 0 | 0 | 952 B |
| master | ExecuteAsync |
netcoreapp3.1 | 1.6μs | 0.646ns | 2.5ns | 0.0127 | 0 | 0 | 952 B |
| master | ExecuteAsync |
net472 | 1.86μs | 1.25ns | 4.84ns | 0.144 | 0 | 0 | 915 B |
| #6356 | ExecuteAsync |
net6.0 | 1.26μs | 0.577ns | 2.16ns | 0.0132 | 0 | 0 | 952 B |
| #6356 | ExecuteAsync |
netcoreapp3.1 | 1.64μs | 0.58ns | 2.17ns | 0.013 | 0 | 0 | 952 B |
| #6356 | ExecuteAsync |
net472 | 1.9μs | 0.456ns | 1.71ns | 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.35μs | 2.07ns | 8.01ns | 0.0327 | 0 | 0 | 2.31 KB |
| master | SendAsync |
netcoreapp3.1 | 5.38μs | 3.19ns | 11.9ns | 0.0375 | 0 | 0 | 2.85 KB |
| master | SendAsync |
net472 | 7.33μs | 1.78ns | 6.9ns | 0.494 | 0 | 0 | 3.12 KB |
| #6356 | SendAsync |
net6.0 | 4.45μs | 2.03ns | 7.86ns | 0.0311 | 0 | 0 | 2.31 KB |
| #6356 | SendAsync |
netcoreapp3.1 | 5.27μs | 4.28ns | 16.6ns | 0.0369 | 0 | 0 | 2.85 KB |
| #6356 | SendAsync |
net472 | 7.3μs | 2.44ns | 9.47ns | 0.493 | 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.57μs | 0.551ns | 1.99ns | 0.0228 | 0 | 0 | 1.64 KB |
| master | EnrichedLog |
netcoreapp3.1 | 2.31μs | 1.37ns | 4.94ns | 0.0216 | 0 | 0 | 1.64 KB |
| master | EnrichedLog |
net472 | 2.56μs | 1.45ns | 5.62ns | 0.249 | 0 | 0 | 1.57 KB |
| #6356 | EnrichedLog |
net6.0 | 1.49μs | 0.796ns | 3.08ns | 0.0232 | 0 | 0 | 1.64 KB |
| #6356 | EnrichedLog |
netcoreapp3.1 | 2.24μs | 1.37ns | 5.14ns | 0.0222 | 0 | 0 | 1.64 KB |
| #6356 | EnrichedLog |
net472 | 2.44μs | 0.93ns | 3.48ns | 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 | 120μs | 114ns | 440ns | 0.0602 | 0 | 0 | 4.28 KB |
| master | EnrichedLog |
netcoreapp3.1 | 122μs | 156ns | 584ns | 0 | 0 | 0 | 4.28 KB |
| master | EnrichedLog |
net472 | 151μs | 267ns | 1.03μs | 0.673 | 0.224 | 0 | 4.46 KB |
| #6356 | EnrichedLog |
net6.0 | 118μs | 146ns | 564ns | 0 | 0 | 0 | 4.28 KB |
| #6356 | EnrichedLog |
netcoreapp3.1 | 125μs | 114ns | 442ns | 0 | 0 | 0 | 4.28 KB |
| #6356 | EnrichedLog |
net472 | 152μs | 59.8ns | 224ns | 0.683 | 0.228 | 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.12μs | 0.905ns | 3.5ns | 0.0311 | 0 | 0 | 2.2 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4.38μs | 1.46ns | 5.45ns | 0.0306 | 0 | 0 | 2.2 KB |
| master | EnrichedLog |
net472 | 4.88μs | 1.47ns | 5.69ns | 0.319 | 0 | 0 | 2.02 KB |
| #6356 | EnrichedLog |
net6.0 | 2.99μs | 0.92ns | 3.44ns | 0.0302 | 0 | 0 | 2.2 KB |
| #6356 | EnrichedLog |
netcoreapp3.1 | 4.09μs | 1.41ns | 5.47ns | 0.0286 | 0 | 0 | 2.2 KB |
| #6356 | EnrichedLog |
net472 | 4.81μs | 1.02ns | 3.82ns | 0.321 | 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.35μs | 0.558ns | 2.16ns | 0.0162 | 0 | 0 | 1.14 KB |
| master | SendReceive |
netcoreapp3.1 | 1.72μs | 0.984ns | 3.81ns | 0.0147 | 0 | 0 | 1.14 KB |
| master | SendReceive |
net472 | 2.1μs | 1.87ns | 7.25ns | 0.183 | 0 | 0 | 1.16 KB |
| #6356 | SendReceive |
net6.0 | 1.34μs | 1.53ns | 5.93ns | 0.0162 | 0 | 0 | 1.14 KB |
| #6356 | SendReceive |
netcoreapp3.1 | 1.73μs | 0.487ns | 1.82ns | 0.0156 | 0 | 0 | 1.14 KB |
| #6356 | SendReceive |
net472 | 2.15μs | 1.64ns | 6.34ns | 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.79μs | 0.924ns | 3.58ns | 0.0224 | 0 | 0 | 1.6 KB |
| master | EnrichedLog |
netcoreapp3.1 | 3.87μs | 1.35ns | 5.21ns | 0.0213 | 0 | 0 | 1.65 KB |
| master | EnrichedLog |
net472 | 4.36μs | 1.97ns | 7.38ns | 0.323 | 0 | 0 | 2.04 KB |
| #6356 | EnrichedLog |
net6.0 | 2.72μs | 1.15ns | 4.45ns | 0.0218 | 0 | 0 | 1.6 KB |
| #6356 | EnrichedLog |
netcoreapp3.1 | 3.92μs | 0.863ns | 3.23ns | 0.0217 | 0 | 0 | 1.65 KB |
| #6356 | EnrichedLog |
net472 | 4.35μs | 4.84ns | 18.7ns | 0.322 | 0 | 0 | 2.04 KB |
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️
Slower ⚠️ in #6356
Benchmark
diff/base
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0
1.132
475.52
538.44
| Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 | 1.132 | 475.52 | 538.44 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | StartFinishSpan |
net6.0 | 447ns | 0.985ns | 3.81ns | 0.00811 | 0 | 0 | 576 B |
| master | StartFinishSpan |
netcoreapp3.1 | 581ns | 1.33ns | 4.98ns | 0.00753 | 0 | 0 | 576 B |
| master | StartFinishSpan |
net472 | 585ns | 0.801ns | 3.1ns | 0.0917 | 0 | 0 | 578 B |
| master | StartFinishScope |
net6.0 | 476ns | 0.665ns | 2.58ns | 0.00966 | 0 | 0 | 696 B |
| master | StartFinishScope |
netcoreapp3.1 | 729ns | 1.21ns | 4.38ns | 0.00953 | 0 | 0 | 696 B |
| master | StartFinishScope |
net472 | 860ns | 2.31ns | 8.94ns | 0.104 | 0 | 0 | 658 B |
| #6356 | StartFinishSpan |
net6.0 | 404ns | 0.604ns | 2.34ns | 0.00802 | 0 | 0 | 576 B |
| #6356 | StartFinishSpan |
netcoreapp3.1 | 624ns | 1.6ns | 6.2ns | 0.00772 | 0 | 0 | 576 B |
| #6356 | StartFinishSpan |
net472 | 619ns | 0.817ns | 3.16ns | 0.0917 | 0 | 0 | 578 B |
| #6356 | StartFinishScope |
net6.0 | 539ns | 0.653ns | 2.53ns | 0.00964 | 0 | 0 | 696 B |
| #6356 | StartFinishScope |
netcoreapp3.1 | 752ns | 0.829ns | 3.21ns | 0.00924 | 0 | 0 | 696 B |
| #6356 | StartFinishScope |
net472 | 885ns | 2.15ns | 8.32ns | 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 | 602ns | 1.3ns | 5.03ns | 0.00969 | 0 | 0 | 696 B |
| master | RunOnMethodBegin |
netcoreapp3.1 | 895ns | 2.22ns | 8.32ns | 0.00956 | 0 | 0 | 696 B |
| master | RunOnMethodBegin |
net472 | 1.13μs | 2.37ns | 9.18ns | 0.104 | 0 | 0 | 658 B |
| #6356 | RunOnMethodBegin |
net6.0 | 671ns | 1.25ns | 4.83ns | 0.00977 | 0 | 0 | 696 B |
| #6356 | RunOnMethodBegin |
netcoreapp3.1 | 932ns | 1.93ns | 7.48ns | 0.00931 | 0 | 0 | 696 B |
| #6356 | RunOnMethodBegin |
net472 | 1.11μs | 1.31ns | 5.06ns | 0.104 | 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 (6356) (11.250M) : 0, 11249747
master (10.987M) : 0, 10986728
benchmarks/2.9.0 (11.033M) : 0, 11032866
section Automatic
This PR (6356) (7.149M) : 0, 7149415
master (7.175M) : 0, 7174684
benchmarks/2.9.0 (7.786M) : 0, 7785853
section Trace stats
master (7.577M) : 0, 7577344
section Manual
master (11.201M) : 0, 11201309
section Manual + Automatic
This PR (6356) (6.740M) : 0, 6739672
master (6.769M) : 0, 6769214
section DD_TRACE_ENABLED=0
master (10.257M) : 0, 10257268
gantt
title Throughput Linux arm64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6356) (9.438M) : 0, 9437808
master (9.557M) : 0, 9557319
benchmarks/2.9.0 (9.495M) : 0, 9494821
section Automatic
This PR (6356) (6.489M) : 0, 6489097
master (6.368M) : 0, 6367805
section Trace stats
master (6.673M) : 0, 6672869
section Manual
master (9.631M) : 0, 9630961
section Manual + Automatic
This PR (6356) (5.993M) : 0, 5993283
master (5.951M) : 0, 5951439
section DD_TRACE_ENABLED=0
master (8.900M) : 0, 8899929
gantt
title Throughput Windows x64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6356) (10.497M) : 0, 10497333
master (9.199M) : 0, 9198633
benchmarks/2.9.0 (10.020M) : 0, 10019592
section Automatic
This PR (6356) (6.844M) : 0, 6843518
master (6.083M) : 0, 6082614
benchmarks/2.9.0 (7.255M) : 0, 7255257
section Trace stats
master (6.603M) : 0, 6602631
section Manual
master (9.506M) : 0, 9505886
section Manual + Automatic
This PR (6356) (6.326M) : 0, 6325779
master (5.789M) : 0, 5788592
section DD_TRACE_ENABLED=0
master (8.972M) : 0, 8971897
|
…6356) ## Summary of changes Use `AsyncManualResetEvent` instead of `ManualResetEventSlim` in the DSM writer ## Reason for change Using `ManualResetEventSlim` means we hog a ThreadPool thread for a potentially long time. Using `async`/`await` releases it. ## Implementation details We have already vendored a `AsyncManualResetEvent` based on [the AsyncEx version](https://github.com/StephenCleary/AsyncEx/blob/master/src/Nito.AsyncEx.Coordination/AsyncManualResetEvent.cs) so just switched to that ## Test coverage Covered by existing, if it passes 👍
Summary of changes
Use
AsyncManualResetEventinstead ofManualResetEventSlimin the DSM writerReason for change
Using
ManualResetEventSlimmeans we hog a ThreadPool thread for a potentially long time. Usingasync/awaitreleases it.Implementation details
We have already vendored a
AsyncManualResetEventbased on the AsyncEx version so just switched to thatTest coverage
Covered by existing, if it passes 👍