Small testing improvements#3222
Merged
Merged
Conversation
This comment has been minimized.
This comment has been minimized.
Seeing occasional flake on arm64 specifically
The StatsTests create standalone (i.e. non-static-global) `Tracer` instances, which in turn creates `TracerManager` instances. The tests were specifically flushing and closing the associated AgentWriter (by way of a helper internal method on `Tracer`), but this left all the other background services (e.g. the `DiscoveryService`) running in the background. When the test finished, and the agent shutdown, those services would keep running in the background, trying to hit a non-existent agent, and writing a log each time
andrewlock
force-pushed
the
andrew/testing-improvements
branch
from
September 16, 2022 12:51
3461019 to
da1508a
Compare
Member
Author
Benchmarks Report 🐌Benchmarks for #3222 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AppSecBodyBenchmark - Slower
|
| Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.AppSecBodyBenchmark.AllCycleMoreComplexBody‑netcoreapp3.1 | 1.714 | 234.05 | 401.18 | several? |
| Benchmarks.Trace.AppSecBodyBenchmark.AllCycleSimpleBody‑netcoreapp3.1 | 1.663 | 237.85 | 395.42 | several? |
| Benchmarks.Trace.AppSecBodyBenchmark.BodyExtractorSimpleBody‑netcoreapp3.1 | 1.526 | 219.64 | 335.16 | several? |
| Benchmarks.Trace.AppSecBodyBenchmark.BodyExtractorMoreComplexBody‑netcoreapp3.1 | 1.275 | 11,857.82 | 15,114.27 | |
| Benchmarks.Trace.AppSecBodyBenchmark.AllCycleSimpleBody‑net472 | 1.185 | 179.75 | 212.99 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | AllCycleSimpleBody |
net472 | 180ns | 0.139ns | 0.502ns | 0.0676 | 9.03E-05 | 0 | 425 B |
| master | AllCycleSimpleBody |
netcoreapp3.1 | 238ns | 0.261ns | 0.976ns | 0.00592 | 0 | 0 | 424 B |
| master | AllCycleMoreComplexBody |
net472 | 179ns | 0.124ns | 0.48ns | 0.0638 | 0 | 0 | 401 B |
| master | AllCycleMoreComplexBody |
netcoreapp3.1 | 234ns | 0.22ns | 0.792ns | 0.00554 | 0 | 0 | 400 B |
| master | BodyExtractorSimpleBody |
net472 | 270ns | 0.244ns | 0.945ns | 0.0574 | 0 | 0 | 361 B |
| master | BodyExtractorSimpleBody |
netcoreapp3.1 | 220ns | 0.335ns | 1.25ns | 0.00366 | 0 | 0 | 272 B |
| master | BodyExtractorMoreComplexBody |
net472 | 15.2μs | 12ns | 46.6ns | 1.21 | 0.0152 | 0 | 7.62 KB |
| master | BodyExtractorMoreComplexBody |
netcoreapp3.1 | 11.9μs | 14.7ns | 56.8ns | 0.0888 | 0 | 0 | 6.75 KB |
| #3222 | AllCycleSimpleBody |
net472 | 212ns | 1.11ns | 5.57ns | 0.0676 | 0 | 0 | 425 B |
| #3222 | AllCycleSimpleBody |
netcoreapp3.1 | 395ns | 7.13ns | 71.3ns | 0.00574 | 0 | 0 | 424 B |
| #3222 | AllCycleMoreComplexBody |
net472 | 195ns | 1.09ns | 7.41ns | 0.0637 | 0 | 0 | 401 B |
| #3222 | AllCycleMoreComplexBody |
netcoreapp3.1 | 399ns | 5.1ns | 50.5ns | 0.00548 | 0 | 0 | 400 B |
| #3222 | BodyExtractorSimpleBody |
net472 | 276ns | 1.16ns | 4.93ns | 0.0574 | 0 | 0 | 361 B |
| #3222 | BodyExtractorSimpleBody |
netcoreapp3.1 | 335ns | 3.87ns | 38.6ns | 0.00367 | 0 | 0 | 272 B |
| #3222 | BodyExtractorMoreComplexBody |
net472 | 15.6μs | 76ns | 304ns | 1.21 | 0.0156 | 0 | 7.62 KB |
| #3222 | BodyExtractorMoreComplexBody |
netcoreapp3.1 | 15.3μs | 115ns | 1.15μs | 0.0859 | 0 | 0 | 6.75 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 |
net472 | 0ns | 0ns | 0ns | 0 | 0 | 0 | 0 b |
| master | SendRequest |
netcoreapp3.1 | 183μs | 282ns | 1.09μs | 0.181 | 0 | 0 | 20.6 KB |
| #3222 | SendRequest |
net472 | 0ns | 0ns | 0ns | 0 | 0 | 0 | 0 b |
| #3222 | SendRequest |
netcoreapp3.1 | 185μs | 270ns | 1.05μs | 0.275 | 0 | 0 | 20.6 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 |
net472 | 1.82μs | 2.43ns | 9.1ns | 0.15 | 0.000901 | 0 | 947 B |
| master | ExecuteNonQuery |
netcoreapp3.1 | 1.47μs | 0.61ns | 2.28ns | 0.0125 | 0 | 0 | 936 B |
| #3222 | ExecuteNonQuery |
net472 | 1.84μs | 0.953ns | 3.57ns | 0.15 | 0.000905 | 0 | 947 B |
| #3222 | ExecuteNonQuery |
netcoreapp3.1 | 1.41μs | 0.376ns | 1.45ns | 0.0119 | 0 | 0 | 936 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 |
net472 | 2.62μs | 1.84ns | 6.87ns | 0.183 | 0 | 0 | 1.16 KB |
| master | CallElasticsearch |
netcoreapp3.1 | 1.57μs | 0.628ns | 2.27ns | 0.0148 | 0 | 0 | 1.1 KB |
| master | CallElasticsearchAsync |
net472 | 2.8μs | 1.44ns | 5.59ns | 0.204 | 0 | 0 | 1.29 KB |
| master | CallElasticsearchAsync |
netcoreapp3.1 | 1.63μs | 0.913ns | 3.54ns | 0.0163 | 0 | 0 | 1.22 KB |
| #3222 | CallElasticsearch |
net472 | 2.64μs | 1.88ns | 7.29ns | 0.183 | 0 | 0 | 1.16 KB |
| #3222 | CallElasticsearch |
netcoreapp3.1 | 1.55μs | 0.897ns | 3.47ns | 0.0146 | 0 | 0 | 1.1 KB |
| #3222 | CallElasticsearchAsync |
net472 | 2.69μs | 0.884ns | 3.31ns | 0.205 | 0 | 0 | 1.29 KB |
| #3222 | CallElasticsearchAsync |
netcoreapp3.1 | 1.62μs | 0.599ns | 2.32ns | 0.0163 | 0 | 0 | 1.22 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 |
net472 | 2.84μs | 6.69ns | 25.9ns | 0.225 | 0 | 0 | 1.42 KB |
| master | ExecuteAsync |
netcoreapp3.1 | 1.65μs | 2.43ns | 9.07ns | 0.0182 | 0 | 0 | 1.34 KB |
| #3222 | ExecuteAsync |
net472 | 2.85μs | 7.71ns | 29.9ns | 0.225 | 0 | 0 | 1.42 KB |
| #3222 | ExecuteAsync |
netcoreapp3.1 | 1.67μs | 4.22ns | 16.3ns | 0.0182 | 0 | 0 | 1.34 KB |
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | SendAsync |
net472 | 5.73μs | 13.5ns | 52.1ns | 0.438 | 0.00283 | 0 | 2.77 KB |
| master | SendAsync |
netcoreapp3.1 | 3.64μs | 8.47ns | 32.8ns | 0.0345 | 0 | 0 | 2.6 KB |
| #3222 | SendAsync |
net472 | 5.72μs | 15.6ns | 58.5ns | 0.438 | 0 | 0 | 2.77 KB |
| #3222 | SendAsync |
netcoreapp3.1 | 3.71μs | 8.82ns | 34.2ns | 0.0354 | 0 | 0 | 2.6 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 |
net472 | 3.15μs | 3.7ns | 14.3ns | 0.287 | 0 | 0 | 1.81 KB |
| master | EnrichedLog |
netcoreapp3.1 | 2.49μs | 1.6ns | 5.98ns | 0.0251 | 0 | 0 | 1.85 KB |
| #3222 | EnrichedLog |
net472 | 3.23μs | 2.71ns | 10.5ns | 0.287 | 0 | 0 | 1.81 KB |
| #3222 | EnrichedLog |
netcoreapp3.1 | 2.52μs | 1.79ns | 6.95ns | 0.0253 | 0 | 0 | 1.85 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 |
net472 | 153μs | 120ns | 451ns | 0.699 | 0.233 | 0 | 4.65 KB |
| master | EnrichedLog |
netcoreapp3.1 | 118μs | 201ns | 777ns | 0.0589 | 0 | 0 | 4.49 KB |
| #3222 | EnrichedLog |
net472 | 153μs | 176ns | 683ns | 0.688 | 0.229 | 0 | 4.65 KB |
| #3222 | EnrichedLog |
netcoreapp3.1 | 119μs | 252ns | 975ns | 0 | 0 | 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 |
net472 | 5.93μs | 14.7ns | 57.1ns | 0.567 | 0.00295 | 0 | 3.59 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4.46μs | 11.2ns | 43.3ns | 0.0545 | 0 | 0 | 3.91 KB |
| #3222 | EnrichedLog |
net472 | 5.77μs | 14.3ns | 55.4ns | 0.568 | 0.0029 | 0 | 3.59 KB |
| #3222 | EnrichedLog |
netcoreapp3.1 | 4.27μs | 7.66ns | 27.6ns | 0.0533 | 0 | 0 | 3.91 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 |
net472 | 2.31μs | 3.08ns | 11.9ns | 0.217 | 0 | 0 | 1.37 KB |
| master | SendReceive |
netcoreapp3.1 | 1.85μs | 1.08ns | 3.88ns | 0.0175 | 0 | 0 | 1.32 KB |
| #3222 | SendReceive |
net472 | 2.39μs | 2.13ns | 8.25ns | 0.217 | 0 | 0 | 1.37 KB |
| #3222 | SendReceive |
netcoreapp3.1 | 1.86μs | 0.689ns | 2.67ns | 0.0176 | 0 | 0 | 1.32 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 |
net472 | 4.99μs | 1.66ns | 6.43ns | 0.354 | 0 | 0 | 2.23 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4.27μs | 2.95ns | 11.4ns | 0.0241 | 0 | 0 | 1.8 KB |
| #3222 | EnrichedLog |
net472 | 4.98μs | 2.1ns | 8.13ns | 0.353 | 0 | 0 | 2.23 KB |
| #3222 | EnrichedLog |
netcoreapp3.1 | 4.35μs | 1.56ns | 6.05ns | 0.0239 | 0 | 0 | 1.8 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 |
net472 | 1.19μs | 0.351ns | 1.36ns | 0.129 | 0 | 0 | 810 B |
| master | StartFinishSpan |
netcoreapp3.1 | 918ns | 0.352ns | 1.27ns | 0.0101 | 0 | 0 | 760 B |
| master | StartFinishScope |
net472 | 1.38μs | 5.01ns | 19.4ns | 0.142 | 0.00068 | 0 | 891 B |
| master | StartFinishScope |
netcoreapp3.1 | 1.07μs | 0.308ns | 1.11ns | 0.0118 | 0 | 0 | 880 B |
| #3222 | StartFinishSpan |
net472 | 1.21μs | 1.06ns | 4.1ns | 0.128 | 0 | 0 | 810 B |
| #3222 | StartFinishSpan |
netcoreapp3.1 | 916ns | 0.953ns | 3.69ns | 0.0101 | 0 | 0 | 760 B |
| #3222 | StartFinishScope |
net472 | 1.36μs | 0.619ns | 2.31ns | 0.141 | 0 | 0 | 891 B |
| #3222 | StartFinishScope |
netcoreapp3.1 | 1.15μs | 2.79ns | 10.8ns | 0.012 | 0 | 0 | 880 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 |
net472 | 1.57μs | 0.971ns | 3.63ns | 0.141 | 0 | 0 | 891 B |
| master | RunOnMethodBegin |
netcoreapp3.1 | 1.13μs | 0.586ns | 2.27ns | 0.0118 | 0 | 0 | 880 B |
| #3222 | RunOnMethodBegin |
net472 | 1.51μs | 0.657ns | 2.54ns | 0.141 | 0 | 0 | 891 B |
| #3222 | RunOnMethodBegin |
netcoreapp3.1 | 1.13μs | 0.525ns | 1.96ns | 0.0118 | 0 | 0 | 880 B |
Member
Author
Code Coverage Report 📊✔️ Merging #3222 into master will not change line coverage
View the full report for further details: Datadog.Trace Breakdown ✔️
The following classes have significant coverage changes.
View the full reports for further details: |
pierotibou
approved these changes
Sep 16, 2022
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary of changes
BatchingSink.AfterMultipleFailures_SinkIsPermanentlyDisabled()StatsTestsso it correctly shuts down all background processesDiscoveryServiceto confirm that we don't check in a tight loopReason for change
Bump the timeout in
BatchingSink.AfterMultipleFailures_SinkIsPermanentlyDisabled()I have seen this fail a couple of times in seemingly unrelated PRs. Not sure exactly why, probably nothing, but given it's failing on a mutex timeout, the easy fix is to bump that up.
Update
StatsTestsso it correctly shuts down all background processesWhen investigating a failing integration test, I noticed that the log file was flooded with warnings like these (130,000 lines of warnings!)
[WRN] Error discovering available agent services System.Net.WebException: Connection refused Connection refusedI eventually tracked this down to the
StatsTests, but it was only reproduced when running the whole suite. I eventually traced it down to the fact that the test creates aTracerManagerimplicitly (by creating aTracer, but it doesn't dispose theTracerManager- it was closing theAgentWriterexplicitly but that meant the discovery service (and other services if they were enabled) were still running. After the mock agent shut down, these would start throwing logs.Add extra test for
DiscoveryServiceto confirm that we don't check in a tight loopThe aforementioned logs were written in a very tight loop (every 1ms!), so I was concerned that we had an error in our retry logic. I wrote this test to reproduce it, but it seemed fine, so may be a different issue. Keeping the test for now anyway.
Implementation details
Update
StatsTestsso it correctly shuts down all background processesExposed an internal
ShutdownAsyncmethod on theTracerManager(for testing only) that can be used to shutdown all the running services. Removed the (now obsolete)FlushAndShutdownAsyncon theTracer.Test coverage
Covered by existing tests or added new ones. Checking the integration tests logs showed the problem has gone now
Other details
NullDiscoveryServiceimplementation that we use by default in the tests (as we do withNullTelemetryService). The changes here are still required however, asStatsTestsexplicitly requires a functioning DiscoveryService