Skip to content

Small testing improvements#3222

Merged
andrewlock merged 4 commits into
masterfrom
andrew/testing-improvements
Sep 20, 2022
Merged

Small testing improvements#3222
andrewlock merged 4 commits into
masterfrom
andrew/testing-improvements

Conversation

@andrewlock

@andrewlock andrewlock commented Sep 16, 2022

Copy link
Copy Markdown
Member

Summary of changes

  • Bump the timeout in BatchingSink.AfterMultipleFailures_SinkIsPermanentlyDisabled()
  • Delete unused code
  • Update StatsTests so it correctly shuts down all background processes
  • Add extra test for DiscoveryService to confirm that we don't check in a tight loop

Reason 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 StatsTests so it correctly shuts down all background processes

When 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 refused

2022-09-15 14:00:21.852 +00:00 [WRN] Error discovering available agent services System.Net.WebException: Connection refused Connection refused
 ---> System.Net.Http.HttpRequestException: Connection refused
 ---> System.Net.Sockets.SocketException (111): Connection refused
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at System.Net.Http.ConnectHelper.ConnectAsync(String host, Int32 port, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.ConnectAsync(HttpRequestMessage request, Boolean allowHttp2, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.CreateHttp11ConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.GetHttpConnectionAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpConnectionPool.SendWithRetryAsync(HttpRequestMessage request, Boolean doRequestAuth, CancellationToken cancellationToken)
   at System.Net.Http.RedirectHandler.SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
   at System.Net.Http.HttpClient.FinishSendAsyncUnbuffered(Task`1 sendTask, HttpRequestMessage request, CancellationTokenSource cts, Boolean disposeCts)
   at System.Net.HttpWebRequest.SendRequest()
   at System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   --- End of inner exception stack trace ---
   at System.Net.HttpWebRequest.EndGetResponse(IAsyncResult asyncResult)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at Datadog.Trace.Agent.Transports.ApiWebRequest.GetAsync() in /project/tracer/src/Datadog.Trace/Agent/Transports/ApiWebRequest.cs:line 52
   at Datadog.Trace.Agent.DiscoveryService.DiscoveryService.FetchConfigurationLoopAsync() in /project/tracer/src/Datadog.Trace/Agent/DiscoveryService/DiscoveryService.cs:line 154
 { MachineName: ".", Process: "[142 dotnet]", AppDomain: "[1 testhost]", TracerVersion: "2.15.0.0" }

I 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 a TracerManager implicitly (by creating a Tracer, but it doesn't dispose the TracerManager - it was closing the AgentWriter explicitly 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 DiscoveryService to confirm that we don't check in a tight loop

The 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 StatsTests so it correctly shuts down all background processes

Exposed an internal ShutdownAsync method on the TracerManager (for testing only) that can be used to shutdown all the running services. Removed the (now obsolete) FlushAndShutdownAsync on the Tracer.

Test coverage

Covered by existing tests or added new ones. Checking the integration tests logs showed the problem has gone now

Other details

  • We will likely have similar issues with the discovery service in other places. I'll check the logs to see if there's any more evidence of it. We may want to consider a NullDiscoveryService implementation that we use by default in the tests (as we do with NullTelemetryService). The changes here are still required however, as StatsTests explicitly requires a functioning DiscoveryService
  • @pierotibou suggested we update our logs to add a sanity check for the number of logs written. I agree, but haven't done it here, as want to make sure we get the discovery service stuff under control first

@andrewlock andrewlock added area:tests unit tests, integration tests type:refactor labels Sep 16, 2022
@andrewlock
andrewlock requested a review from a team as a code owner September 16, 2022 12:01
@andrewlock

This comment has been minimized.

@bouwkast bouwkast left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

Looks good to me!

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
andrewlock force-pushed the andrew/testing-improvements branch from 3461019 to da1508a Compare September 16, 2022 12:51
@andrewlock

Copy link
Copy Markdown
Member Author

Benchmarks Report 🐌

Benchmarks for #3222 compared to master:

  • 5 benchmarks are slower, with geometric mean 1.457
  • 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.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net472 723μs 397ns 1.48μs 0.359 0 0 3.18 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 469μs 141ns 547ns 0 0 0 2.58 KB
#3222 WriteAndFlushEnrichedTraces net472 713μs 749ns 2.8μs 0.357 0 0 3.18 KB
#3222 WriteAndFlushEnrichedTraces netcoreapp3.1 465μs 269ns 1.04μs 0 0 0 2.58 KB
Benchmarks.Trace.AppSecBodyBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #3222

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

@andrewlock

Copy link
Copy Markdown
Member Author

Code Coverage Report 📊

✔️ Merging #3222 into master will not change line coverage
✔️ Merging #3222 into master will not change branch coverage
⛔ Merging #3222 into master will will increase complexity by 1

master #3222 Change
Lines 18012 / 24587 18025 / 24588
Lines % 73% 73% 0% ✔️
Branches 10604 / 15064 10612 / 15064
Branches % 70% 70% 0% ✔️
Complexity 16290 16291 1

View the full report for further details:

Datadog.Trace Breakdown ✔️

master #3222 Change
Lines % 73% 73% 0% ✔️
Branches % 70% 70% 0% ✔️
Complexity 16290 16291 1

The following classes have significant coverage changes.

File Line coverage change Branch coverage change Complexity change
Datadog.Trace.Ci.CIVisibility 5% ✔️ 6% ✔️ 0 ✔️
Datadog.Trace.TracerManager 6% ✔️ 11% ✔️ 2
Datadog.Trace.Telemetry.NullTelemetryController 10% ✔️ 0% ✔️ 0 ✔️
Datadog.Trace.Logging.DirectSubmission.Sink.NullDatadogSink 25% ✔️ 0% ✔️ 0 ✔️
Datadog.Trace.Logging.DirectSubmission.DirectLogSubmissionManager 33% ✔️ 33% ✔️ 0 ✔️

View the full reports for further details:

@andrewlock
andrewlock merged commit 2927bb8 into master Sep 20, 2022
@andrewlock
andrewlock deleted the andrew/testing-improvements branch September 20, 2022 08:45
@github-actions github-actions Bot added this to the vNext milestone Sep 20, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area:tests unit tests, integration tests type:refactor

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants