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.

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 smoke test for config builder instrumentation issue #6224

Merged
merged 2 commits into from
Nov 4, 2024

Conversation

andrewlock
Copy link
Member

Summary of changes

Adds a smoke test for the issue fixed in #6147

Reason for change

The issue in #6147 is complex and subtle, with a high risk of regression, so we want to have smoke tests to catch it`

Implementation details

Add a sample app very similar to the one tested with in #6147. Without the fix, the test fails with

<b> Description: </b>An error occurred during the processing of a configuration file required to service this request. Please review the specific error details below and modify your configuration file appropriately.
<br><br>
<b> Parser Error Message: </b>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.<br><br>

After the fix (now merged) the tests pass

Test coverage

This is primarily a smoke test, so we confirm

  • The sites are running and responding to HTTP requests correctly
  • We instrument the application (it has logs)
  • There are no errors in the logs

Other details

For some reason, I had massive issues getting the app to "recognize" the DD_TRACE_AGENT_URL=http://test-agent.windows:8126 env var setting that's required to talk to the test agent. I have no idea why, and the only resolution I could find was to use powershell to set the variables inside the docker image

@andrewlock andrewlock added area:tests unit tests, integration tests area:test-apps apps used to test integrations labels Oct 31, 2024
@andrewlock andrewlock requested review from a team as code owners October 31, 2024 16:17
@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Oct 31, 2024

Datadog Report

Branch report: aspnet-repro
Commit report: dbdc176
Test service: dd-trace-dotnet

✅ 0 Failed, 369352 Passed, 2100 Skipped, 14h 53m 45.83s Total Time

@andrewlock
Copy link
Member Author

andrewlock commented Oct 31, 2024

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 (6224) - mean (70ms)  : 68, 73
     .   : milestone, 70,
    master - mean (70ms)  : 68, 72
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (6224) - mean (1,118ms)  : 1095, 1141
     .   : milestone, 1118,
    master - mean (1,119ms)  : 1098, 1141
     .   : milestone, 1119,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6224) - mean (110ms)  : 106, 114
     .   : milestone, 110,
    master - mean (110ms)  : 107, 114
     .   : milestone, 110,

    section CallTarget+Inlining+NGEN
    This PR (6224) - mean (780ms)  : 764, 795
     .   : milestone, 780,
    master - mean (782ms)  : 763, 801
     .   : milestone, 782,

Loading
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6224) - mean (93ms)  : 90, 96
     .   : milestone, 93,
    master - mean (93ms)  : 90, 96
     .   : milestone, 93,

    section CallTarget+Inlining+NGEN
    This PR (6224) - mean (733ms)  : 714, 752
     .   : milestone, 733,
    master - mean (738ms)  : 722, 753
     .   : milestone, 738,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6224) - mean (196ms)  : 193, 199
     .   : milestone, 196,
    master - mean (190ms)  : 188, 193
     .   : milestone, 190,

    section CallTarget+Inlining+NGEN
    This PR (6224) - mean (1,260ms)  : 1235, 1286
     .   : milestone, 1260,
    master - mean (1,225ms)  : 1202, 1248
     .   : milestone, 1225,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6224) - mean (285ms)  : 280, 290
     .   : milestone, 285,
    master - mean (287ms)  : 257, 317
     .   : milestone, 287,

    section CallTarget+Inlining+NGEN
    This PR (6224) - mean (983ms)  : 967, 1000
     .   : milestone, 983,
    master - mean (952ms)  : 931, 973
     .   : milestone, 952,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6224) - mean (272ms)  : 267, 277
     .   : milestone, 272,
    master - mean (265ms)  : 261, 269
     .   : milestone, 265,

    section CallTarget+Inlining+NGEN
    This PR (6224) - mean (965ms)  : 945, 984
     .   : milestone, 965,
    master - mean (953ms)  : 917, 990
     .   : milestone, 953,

Loading

@andrewlock
Copy link
Member Author

Benchmarks Report for tracer 🐌

Benchmarks for #6224 compared to master:

  • All benchmarks have the same speed
  • 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 7.7μs 44.5ns 378ns 0.0151 0.00756 0 5.43 KB
master StartStopWithChild netcoreapp3.1 9.91μs 54.8ns 338ns 0.0196 0.00979 0 5.61 KB
master StartStopWithChild net472 16.4μs 58.8ns 228ns 1 0.3 0.081 6.06 KB
#6224 StartStopWithChild net6.0 7.75μs 43.5ns 285ns 0.0158 0.00792 0 5.43 KB
#6224 StartStopWithChild netcoreapp3.1 9.74μs 54.1ns 342ns 0.0233 0.0093 0 5.61 KB
#6224 StartStopWithChild net472 16.6μs 50.4ns 195ns 1.04 0.329 0.0904 6.07 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 492μs 477ns 1.85μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 660μs 300ns 1.12μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 838μs 611ns 2.28μs 0.417 0 0 3.3 KB
#6224 WriteAndFlushEnrichedTraces net6.0 491μs 242ns 937ns 0 0 0 2.7 KB
#6224 WriteAndFlushEnrichedTraces netcoreapp3.1 660μs 345ns 1.29μs 0 0 0 2.7 KB
#6224 WriteAndFlushEnrichedTraces net472 839μs 577ns 2.16μs 0.417 0 0 3.3 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 214μs 1.25μs 12.1μs 0.218 0 0 18.45 KB
master SendRequest netcoreapp3.1 241μs 1.37μs 10.5μs 0.236 0 0 20.61 KB
master SendRequest net472 0.00301ns 0.0011ns 0.00426ns 0 0 0 0 b
#6224 SendRequest net6.0 216μs 1.25μs 11.6μs 0.201 0 0 18.45 KB
#6224 SendRequest netcoreapp3.1 241μs 1.41μs 12.5μs 0.234 0 0 20.61 KB
#6224 SendRequest net472 0.000326ns 0.000196ns 0.00076ns 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 616μs 3.53μs 25.4μs 0.625 0 0 41.65 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 745μs 3.82μs 19.1μs 0.342 0 0 41.77 KB
master WriteAndFlushEnrichedTraces net472 926μs 4.67μs 20.4μs 8.4 2.33 0.466 53.33 KB
#6224 WriteAndFlushEnrichedTraces net6.0 589μs 2.77μs 11.1μs 0.576 0 0 41.69 KB
#6224 WriteAndFlushEnrichedTraces netcoreapp3.1 721μs 3.7μs 18.9μs 0.355 0 0 41.76 KB
#6224 WriteAndFlushEnrichedTraces net472 869μs 4.45μs 19.9μs 8.42 2.66 0.443 53.35 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.3μs 1.29ns 4.98ns 0.0143 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.77μs 5.81ns 21ns 0.0139 0 0 1.02 KB
master ExecuteNonQuery net472 2.09μs 1.33ns 5.16ns 0.156 0.00105 0 987 B
#6224 ExecuteNonQuery net6.0 1.37μs 2.02ns 7.83ns 0.0143 0 0 1.02 KB
#6224 ExecuteNonQuery netcoreapp3.1 1.72μs 1.06ns 3.97ns 0.013 0 0 1.02 KB
#6224 ExecuteNonQuery net472 2.13μs 1.49ns 5.58ns 0.157 0.00108 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.22μs 0.299ns 1.16ns 0.0135 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.44μs 0.845ns 3.16ns 0.0131 0 0 976 B
master CallElasticsearch net472 2.59μs 2.03ns 7.85ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.38μs 0.775ns 2.9ns 0.0131 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.52μs 0.687ns 2.48ns 0.0138 0 0 1.02 KB
master CallElasticsearchAsync net472 2.58μs 1.61ns 6.24ns 0.167 0 0 1.05 KB
#6224 CallElasticsearch net6.0 1.22μs 0.907ns 3.51ns 0.014 0 0 976 B
#6224 CallElasticsearch netcoreapp3.1 1.55μs 0.865ns 3.12ns 0.0131 0 0 976 B
#6224 CallElasticsearch net472 2.56μs 1.13ns 4.09ns 0.157 0 0 995 B
#6224 CallElasticsearchAsync net6.0 1.27μs 0.477ns 1.85ns 0.0133 0 0 952 B
#6224 CallElasticsearchAsync netcoreapp3.1 1.63μs 4.1ns 15.3ns 0.0136 0 0 1.02 KB
#6224 CallElasticsearchAsync net472 2.62μs 1.75ns 6.56ns 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.34μs 0.467ns 1.81ns 0.0134 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.58μs 0.606ns 2.27ns 0.0126 0 0 952 B
master ExecuteAsync net472 1.75μs 0.676ns 2.62ns 0.145 0 0 915 B
#6224 ExecuteAsync net6.0 1.36μs 0.387ns 1.45ns 0.0136 0 0 952 B
#6224 ExecuteAsync netcoreapp3.1 1.55μs 1.3ns 5.04ns 0.0125 0 0 952 B
#6224 ExecuteAsync net472 1.68μs 1.18ns 4.56ns 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.15μs 2.43ns 9.1ns 0.031 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.17μs 3.02ns 11.7ns 0.0362 0 0 2.76 KB
master SendAsync net472 7.2μs 2.05ns 7.95ns 0.486 0 0 3.07 KB
#6224 SendAsync net6.0 4.18μs 2.09ns 7.83ns 0.0315 0 0 2.22 KB
#6224 SendAsync netcoreapp3.1 5.12μs 1.48ns 5.52ns 0.0358 0 0 2.76 KB
#6224 SendAsync net472 7.26μs 1.76ns 6.83ns 0.486 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.828ns 3.1ns 0.0229 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.23μs 1ns 3.76ns 0.0224 0 0 1.64 KB
master EnrichedLog net472 2.57μs 1ns 3.75ns 0.249 0 0 1.57 KB
#6224 EnrichedLog net6.0 1.57μs 1.03ns 3.99ns 0.0226 0 0 1.64 KB
#6224 EnrichedLog netcoreapp3.1 2.18μs 1.09ns 4.23ns 0.0218 0 0 1.64 KB
#6224 EnrichedLog net472 2.54μs 0.644ns 2.41ns 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 267ns 1.04μs 0.0573 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 121μs 206ns 799ns 0 0 0 4.28 KB
master EnrichedLog net472 152μs 209ns 811ns 0.681 0.227 0 4.46 KB
#6224 EnrichedLog net6.0 117μs 260ns 971ns 0.0591 0 0 4.28 KB
#6224 EnrichedLog netcoreapp3.1 123μs 285ns 1.1μs 0 0 0 4.28 KB
#6224 EnrichedLog net472 153μs 159ns 615ns 0.691 0.23 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.14μs 0.991ns 3.84ns 0.0298 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.12μs 1.39ns 5.2ns 0.0292 0 0 2.2 KB
master EnrichedLog net472 4.84μs 0.87ns 3.37ns 0.319 0 0 2.02 KB
#6224 EnrichedLog net6.0 3.03μs 1.18ns 4.41ns 0.0303 0 0 2.2 KB
#6224 EnrichedLog netcoreapp3.1 4.25μs 1.77ns 6.87ns 0.0296 0 0 2.2 KB
#6224 EnrichedLog net472 4.76μs 0.983ns 3.81ns 0.319 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 1.05ns 4.06ns 0.0162 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.68μs 1.36ns 5.28ns 0.0156 0 0 1.14 KB
master SendReceive net472 2.13μs 5.19ns 20.1ns 0.183 0 0 1.16 KB
#6224 SendReceive net6.0 1.42μs 1.36ns 5.26ns 0.0162 0 0 1.14 KB
#6224 SendReceive netcoreapp3.1 1.71μs 1.26ns 4.55ns 0.0154 0 0 1.14 KB
#6224 SendReceive net472 2.13μs 0.936ns 3.62ns 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.7μs 0.668ns 2.59ns 0.0215 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.95μs 2.14ns 7.4ns 0.0218 0 0 1.65 KB
master EnrichedLog net472 4.49μs 3.45ns 13.4ns 0.323 0 0 2.04 KB
#6224 EnrichedLog net6.0 2.73μs 4.53ns 17.5ns 0.0219 0 0 1.6 KB
#6224 EnrichedLog netcoreapp3.1 3.91μs 3.98ns 15.4ns 0.0215 0 0 1.65 KB
#6224 EnrichedLog net472 4.47μs 1.03ns 3.71ns 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 409ns 0.119ns 0.462ns 0.00802 0 0 576 B
master StartFinishSpan netcoreapp3.1 640ns 0.468ns 1.69ns 0.0078 0 0 576 B
master StartFinishSpan net472 685ns 0.272ns 1.05ns 0.0915 0 0 578 B
master StartFinishScope net6.0 484ns 0.133ns 0.514ns 0.00974 0 0 696 B
master StartFinishScope netcoreapp3.1 675ns 1.26ns 4.88ns 0.00944 0 0 696 B
master StartFinishScope net472 872ns 0.775ns 3ns 0.105 0 0 658 B
#6224 StartFinishSpan net6.0 407ns 0.385ns 1.49ns 0.00816 0 0 576 B
#6224 StartFinishSpan netcoreapp3.1 643ns 0.556ns 2.15ns 0.00768 0 0 576 B
#6224 StartFinishSpan net472 736ns 0.439ns 1.7ns 0.0915 0 0 578 B
#6224 StartFinishScope net6.0 479ns 0.302ns 1.17ns 0.00989 0 0 696 B
#6224 StartFinishScope netcoreapp3.1 742ns 0.263ns 1.02ns 0.00924 0 0 696 B
#6224 StartFinishScope net472 940ns 0.804ns 3.12ns 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 644ns 0.279ns 1.08ns 0.00974 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 983ns 0.62ns 2.4ns 0.00934 0 0 696 B
master RunOnMethodBegin net472 1.17μs 0.278ns 1.08ns 0.104 0 0 658 B
#6224 RunOnMethodBegin net6.0 663ns 0.232ns 0.897ns 0.00968 0 0 696 B
#6224 RunOnMethodBegin netcoreapp3.1 928ns 0.545ns 2.11ns 0.00947 0 0 696 B
#6224 RunOnMethodBegin net472 1.19μs 0.702ns 2.72ns 0.104 0 0 658 B

Copy link
Collaborator

@kevingosse kevingosse left a comment

Choose a reason for hiding this comment

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

You could have simplified the config builder, but whatever

Comment on lines +25 to +26
#pragma warning disable CS1591 // No xml comments for tag literals.
#pragma warning restore CS1591 // No xml comments for tag literals.
Copy link
Collaborator

Choose a reason for hiding this comment

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

:stare:

Copy link
Member Author

Choose a reason for hiding this comment

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

I wanted a "faithful reproduction" of the issue. This seemed critical 😉

// Also, this is a synchronous method. And in single-threaded contexts like ASP.Net
// it can be bad/dangerous to block on async calls. So lets work some TPL voodoo
// to avoid potential deadlocks.
return Task.Run(async () => { return await GetValueAsync(key, string.Empty); }).Result?.Value;
Copy link
Collaborator

Choose a reason for hiding this comment

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

Wow you decided to keep this

Copy link
Member Author

@andrewlock andrewlock Nov 4, 2024

Choose a reason for hiding this comment

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

I won't hide their shame

@andrewlock andrewlock merged commit 64c02f7 into master Nov 4, 2024
74 of 77 checks passed
@andrewlock andrewlock deleted the aspnet-repro branch November 4, 2024 14:56
@github-actions github-actions bot added this to the vNext-v3 milestone Nov 4, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:test-apps apps used to test integrations area:tests unit tests, integration tests
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants