-
Notifications
You must be signed in to change notification settings - Fork 139
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
Add workaround for ASP.NET ConfigBuilder issue #6147
base: master
Are you sure you want to change the base?
Conversation
Datadog ReportBranch report: ✅ 0 Failed, 364588 Passed, 2089 Skipped, 14h 17m 7.37s 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 (6147) - mean (70ms) : 68, 72
. : milestone, 70,
master - mean (70ms) : 67, 72
. : milestone, 70,
section CallTarget+Inlining+NGEN
This PR (6147) - mean (1,109ms) : 1088, 1131
. : milestone, 1109,
master - mean (1,110ms) : 1085, 1135
. : milestone, 1110,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6147) - mean (109ms) : 105, 112
. : milestone, 109,
master - mean (109ms) : 105, 112
. : milestone, 109,
section CallTarget+Inlining+NGEN
This PR (6147) - mean (770ms) : 754, 786
. : milestone, 770,
master - mean (771ms) : 757, 786
. : milestone, 771,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6147) - mean (91ms) : 89, 94
. : milestone, 91,
master - mean (92ms) : 89, 95
. : milestone, 92,
section CallTarget+Inlining+NGEN
This PR (6147) - mean (726ms) : 710, 742
. : milestone, 726,
master - mean (727ms) : 710, 744
. : milestone, 727,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6147) - mean (189ms) : 185, 192
. : milestone, 189,
master - mean (189ms) : 186, 192
. : milestone, 189,
section CallTarget+Inlining+NGEN
This PR (6147) - mean (1,197ms) : 1165, 1229
. : milestone, 1197,
master - mean (1,201ms) : 1179, 1222
. : milestone, 1201,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6147) - mean (274ms) : 270, 278
. : milestone, 274,
master - mean (274ms) : 269, 278
. : milestone, 274,
section CallTarget+Inlining+NGEN
This PR (6147) - mean (940ms) : 917, 962
. : milestone, 940,
master - mean (943ms) : 926, 960
. : milestone, 943,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6147) - mean (265ms) : 258, 272
. : milestone, 265,
master - mean (263ms) : 259, 267
. : milestone, 263,
section CallTarget+Inlining+NGEN
This PR (6147) - mean (923ms) : 904, 942
. : milestone, 923,
master - mean (924ms) : 908, 940
. : milestone, 924,
|
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 (6147) (11.065M) : 0, 11065166
master (11.252M) : 0, 11251784
benchmarks/2.9.0 (11.081M) : 0, 11080577
section Automatic
This PR (6147) (7.352M) : 0, 7352036
master (7.466M) : 0, 7465753
benchmarks/2.9.0 (7.732M) : 0, 7732233
section Trace stats
master (7.766M) : 0, 7765791
section Manual
master (11.114M) : 0, 11114354
section Manual + Automatic
This PR (6147) (6.787M) : 0, 6786664
master (6.846M) : 0, 6845872
section DD_TRACE_ENABLED=0
master (10.389M) : 0, 10388612
gantt
title Throughput Linux arm64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6147) (9.684M) : 0, 9684201
master (9.539M) : 0, 9539093
benchmarks/2.9.0 (9.798M) : 0, 9798067
section Automatic
This PR (6147) (6.571M) : 0, 6570831
master (6.648M) : 0, 6647799
section Trace stats
master (6.855M) : 0, 6855301
section Manual
master (9.525M) : 0, 9525425
section Manual + Automatic
This PR (6147) (6.223M) : 0, 6223200
master (6.161M) : 0, 6160600
section DD_TRACE_ENABLED=0
master (8.832M) : 0, 8832117
gantt
title Throughput Windows x64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6147) (10.241M) : 0, 10241497
master (10.064M) : 0, 10064242
benchmarks/2.9.0 (10.067M) : 0, 10067315
section Automatic
This PR (6147) (6.774M) : 0, 6773677
master (6.841M) : 0, 6841333
benchmarks/2.9.0 (7.552M) : 0, 7552193
section Trace stats
master (7.427M) : 0, 7426854
section Manual
master (10.084M) : 0, 10084210
section Manual + Automatic
This PR (6147) (6.168M) : 0, 6167697
master (6.348M) : 0, 6347556
section DD_TRACE_ENABLED=0
master (9.577M) : 0, 9576577
|
Benchmarks Report for tracer 🐌Benchmarks for #6147 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 - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Fewer allocations 🎉
|
Benchmark | Base Allocated | Diff Allocated | Change | Change % |
---|---|---|---|---|
Benchmarks.Trace.HttpClientBenchmark.SendAsync‑net472 | 3.15 KB | 3.07 KB | -73 B | -2.32% |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | SendAsync |
net6.0 | 4.2μs | 2.3ns | 8.6ns | 0.0295 | 0 | 0 | 2.22 KB |
master | SendAsync |
netcoreapp3.1 | 5.01μs | 3.35ns | 13ns | 0.0375 | 0 | 0 | 2.76 KB |
master | SendAsync |
net472 | 7.66μs | 0.961ns | 3.47ns | 0.498 | 0 | 0 | 3.15 KB |
#6147 | SendAsync |
net6.0 | 4.25μs | 3.11ns | 12ns | 0.0297 | 0 | 0 | 2.22 KB |
#6147 | SendAsync |
netcoreapp3.1 | 5.09μs | 2.12ns | 7.95ns | 0.0356 | 0 | 0 | 2.76 KB |
#6147 | SendAsync |
net472 | 7.38μs | 2.16ns | 8.35ns | 0.487 | 0 | 0 | 3.07 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.766ns | 2.87ns | 0.0228 | 0 | 0 | 1.64 KB |
master | EnrichedLog |
netcoreapp3.1 | 2.14μs | 1.03ns | 3.87ns | 0.0225 | 0 | 0 | 1.64 KB |
master | EnrichedLog |
net472 | 2.61μs | 0.729ns | 2.82ns | 0.249 | 0 | 0 | 1.57 KB |
#6147 | EnrichedLog |
net6.0 | 1.54μs | 0.659ns | 2.46ns | 0.0226 | 0 | 0 | 1.64 KB |
#6147 | EnrichedLog |
netcoreapp3.1 | 2.37μs | 1.26ns | 4.9ns | 0.0224 | 0 | 0 | 1.64 KB |
#6147 | EnrichedLog |
net472 | 2.54μs | 1.97ns | 7.65ns | 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 | 116μs | 125ns | 469ns | 0.0584 | 0 | 0 | 4.28 KB |
master | EnrichedLog |
netcoreapp3.1 | 121μs | 194ns | 701ns | 0.0603 | 0 | 0 | 4.28 KB |
master | EnrichedLog |
net472 | 153μs | 117ns | 454ns | 0.685 | 0.228 | 0 | 4.46 KB |
#6147 | EnrichedLog |
net6.0 | 117μs | 250ns | 968ns | 0.0589 | 0 | 0 | 4.28 KB |
#6147 | EnrichedLog |
netcoreapp3.1 | 120μs | 169ns | 610ns | 0 | 0 | 0 | 4.28 KB |
#6147 | EnrichedLog |
net472 | 153μs | 155ns | 580ns | 0.684 | 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 | 2.96μs | 0.872ns | 3.26ns | 0.031 | 0 | 0 | 2.2 KB |
master | EnrichedLog |
netcoreapp3.1 | 4.1μs | 1.26ns | 4.88ns | 0.0288 | 0 | 0 | 2.2 KB |
master | EnrichedLog |
net472 | 4.96μs | 1.14ns | 4.41ns | 0.321 | 0 | 0 | 2.02 KB |
#6147 | EnrichedLog |
net6.0 | 3.1μs | 1.12ns | 4.05ns | 0.0307 | 0 | 0 | 2.2 KB |
#6147 | EnrichedLog |
netcoreapp3.1 | 4.15μs | 1.1ns | 4.25ns | 0.029 | 0 | 0 | 2.2 KB |
#6147 | EnrichedLog |
net472 | 4.86μs | 1.35ns | 5.04ns | 0.32 | 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.43μs | 0.82ns | 3.18ns | 0.0164 | 0 | 0 | 1.14 KB |
master | SendReceive |
netcoreapp3.1 | 1.76μs | 0.655ns | 2.54ns | 0.0154 | 0 | 0 | 1.14 KB |
master | SendReceive |
net472 | 2.11μs | 0.84ns | 3.25ns | 0.184 | 0.00105 | 0 | 1.16 KB |
#6147 | SendReceive |
net6.0 | 1.51μs | 0.876ns | 3.28ns | 0.0158 | 0 | 0 | 1.14 KB |
#6147 | SendReceive |
netcoreapp3.1 | 1.8μs | 0.836ns | 3.24ns | 0.0153 | 0 | 0 | 1.14 KB |
#6147 | SendReceive |
net472 | 2.14μs | 0.766ns | 2.76ns | 0.184 | 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.8μs | 2.58ns | 9.65ns | 0.0222 | 0 | 0 | 1.6 KB |
master | EnrichedLog |
netcoreapp3.1 | 3.96μs | 1.04ns | 3.9ns | 0.0218 | 0 | 0 | 1.65 KB |
master | EnrichedLog |
net472 | 4.43μs | 2.15ns | 8.32ns | 0.322 | 0 | 0 | 2.04 KB |
#6147 | EnrichedLog |
net6.0 | 2.91μs | 1.23ns | 4.78ns | 0.0218 | 0 | 0 | 1.6 KB |
#6147 | EnrichedLog |
netcoreapp3.1 | 3.66μs | 1.01ns | 3.92ns | 0.0219 | 0 | 0 | 1.65 KB |
#6147 | EnrichedLog |
net472 | 4.48μs | 5.4ns | 19.5ns | 0.323 | 0 | 0 | 2.04 KB |
Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️
Faster 🎉 in #6147
Benchmark
base/diff
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1
1.170
655.37
560.23
Benchmark | base/diff | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 | 1.170 | 655.37 | 560.23 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | StartFinishSpan |
net6.0 | 404ns | 0.213ns | 0.824ns | 0.0081 | 0 | 0 | 576 B |
master | StartFinishSpan |
netcoreapp3.1 | 655ns | 0.38ns | 1.47ns | 0.00786 | 0 | 0 | 576 B |
master | StartFinishSpan |
net472 | 701ns | 0.453ns | 1.7ns | 0.0917 | 0 | 0 | 578 B |
master | StartFinishScope |
net6.0 | 485ns | 0.239ns | 0.924ns | 0.00976 | 0 | 0 | 696 B |
master | StartFinishScope |
netcoreapp3.1 | 758ns | 0.391ns | 1.46ns | 0.00957 | 0 | 0 | 696 B |
master | StartFinishScope |
net472 | 873ns | 0.405ns | 1.57ns | 0.104 | 0 | 0 | 658 B |
#6147 | StartFinishSpan |
net6.0 | 434ns | 0.199ns | 0.743ns | 0.00803 | 0 | 0 | 576 B |
#6147 | StartFinishSpan |
netcoreapp3.1 | 560ns | 0.245ns | 0.948ns | 0.00785 | 0 | 0 | 576 B |
#6147 | StartFinishSpan |
net472 | 710ns | 1.12ns | 4.32ns | 0.0916 | 0 | 0 | 578 B |
#6147 | StartFinishScope |
net6.0 | 513ns | 0.408ns | 1.58ns | 0.0098 | 0 | 0 | 696 B |
#6147 | StartFinishScope |
netcoreapp3.1 | 732ns | 0.823ns | 3.19ns | 0.00945 | 0 | 0 | 696 B |
#6147 | StartFinishScope |
net472 | 947ns | 0.892ns | 3.45ns | 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 | 671ns | 0.323ns | 1.25ns | 0.00977 | 0 | 0 | 696 B |
master | RunOnMethodBegin |
netcoreapp3.1 | 974ns | 1.03ns | 3.84ns | 0.0092 | 0 | 0 | 696 B |
master | RunOnMethodBegin |
net472 | 1.16μs | 0.465ns | 1.8ns | 0.104 | 0 | 0 | 658 B |
#6147 | RunOnMethodBegin |
net6.0 | 684ns | 0.186ns | 0.72ns | 0.00992 | 0 | 0 | 696 B |
#6147 | RunOnMethodBegin |
netcoreapp3.1 | 908ns | 0.471ns | 1.83ns | 0.0094 | 0 | 0 | 696 B |
#6147 | RunOnMethodBegin |
net472 | 1.05μs | 0.673ns | 2.61ns | 0.105 | 0 | 0 | 658 B |
Summary of changes
Adds a check that IisPreStartInit has completed before we run any automatic instrumentations
Reason for change
We recently had a case where a customer was using
AzureKeyVaultConfigBuilder
with ASP.NET's web.config to load configuration intoAppSettings
, which was causing the application to deadlock on startup.After some investigation, we isolated the problem as happening specifically when there are 2 apps running inside an app pool:
CallTargetInvoker
which tries to initialize the tracerAppSettings
so that we can populate configurationSo the key thing is that we need to make sure we don't run our automatic instrumentation until after the IIS pre-init stage is completely, to avoid re-entry and recursion during setup.
Implementation details
The implementation is leveraging work we did years ago to fix essentially the same problem: #1157. The problem back then was with Liblog and NLog, but we did all the work to inject flags for tracking when it is safe to make changes.
Given the native work already exists, it was ultimately pretty simple to fix by making sure we don't run any automatic instrumentations unless the domain as finished pre-initialization.
Test coverage
This is kind of a pain to test because it requires a custom config builder, plus two applications running in an app pool. I tested manually by
ConfigBuilder
based on theAzureKeyVaultConfigBuilder
implementation. The custom builder simply makes a generic HTTP request when a value is requestedweb.config
to set up the builder (see below)The configBuilder 'CustomBuilder' failed while processing the configuration section 'appSettings'.: The ConfigurationBuilder 'CustomBuilder[Microsoft.Configuration.ConfigurationBuilders.CustomConfigBuilder]' has recursively re-entered processing of the 'appSettings' section
(I based my implementation on v3 which specifically detects re-entry)web.config for my dummy test:
Complete test solution is here:
ConfigBuilderIssueRepro.zip
Other details
Fixes: https://datadoghq.atlassian.net/browse/APMS-13426