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.

Sign up for GitHub

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

Jump to bottom

Fix race condition in TelemetryControllerSchedulerTests #6514

Merged
merged 1 commit into from
Jan 9, 2025
Merged

Fix race condition in TelemetryControllerSchedulerTests #6514

merged 1 commit into from
Jan 9, 2025

Conversation

kevingosse
Copy link
Collaborator

Summary of changes

Fix a race condition in TelemetryControllerSchedulerTests.TypicalLoop_WithLogsQueueTrigger.

Reason for change

Flaky test.

Implementation details

In one case, the task returned by _scheduler.WaitForNextInterval() wasn't awaited, which caused the assertion to be evaluated too soon.

@kevingosse kevingosse requested a review from a team as a code owner January 8, 2025 15:33
@kevingosse kevingosse added the area:tests unit tests, integration tests label Jan 8, 2025
@kevingosse kevingosse force-pushed the kevin/fix_telemetry_test branch from 0ce0f49 to 0e0de0e Compare January 8, 2025 16:04
@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Jan 8, 2025 •
edited
Loading

Datadog Report

Branch report: kevin/fix_telemetry_test
Commit report: 0e0de0e
Test service: dd-trace-dotnet

✅ 0 Failed, 240101 Passed, 2112 Skipped, 18h 43m 7.51s Total Time

@andrewlock
Copy link
Member

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 (6514) - mean (69ms)  : 65, 72
     .   : milestone, 69,
    master - mean (69ms)  : 66, 72
     .   : milestone, 69,

    section CallTarget+Inlining+NGEN
    This PR (6514) - mean (979ms)  : 958, 1001
     .   : milestone, 979,
    master - mean (981ms)  : 954, 1008
     .   : milestone, 981,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6514) - mean (108ms)  : 106, 110
     .   : milestone, 108,
    master - mean (107ms)  : 105, 110
     .   : milestone, 107,

    section CallTarget+Inlining+NGEN
    This PR (6514) - mean (677ms)  : 659, 695
     .   : milestone, 677,
    master - mean (678ms)  : 662, 695
     .   : milestone, 678,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6514) - mean (91ms)  : 89, 93
     .   : milestone, 91,
    master - mean (91ms)  : 90, 93
     .   : milestone, 91,

    section CallTarget+Inlining+NGEN
    This PR (6514) - mean (636ms)  : 617, 655
     .   : milestone, 636,
    master - mean (633ms)  : 616, 651
     .   : milestone, 633,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6514) - mean (194ms)  : 190, 199
     .   : milestone, 194,
    master - mean (195ms)  : 189, 202
     .   : milestone, 195,

    section CallTarget+Inlining+NGEN
    This PR (6514) - mean (1,109ms)  : 1073, 1145
     .   : milestone, 1109,
    master - mean (1,104ms)  : 1076, 1132
     .   : milestone, 1104,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6514) - mean (279ms)  : 275, 284
     .   : milestone, 279,
    master - mean (278ms)  : 273, 282
     .   : milestone, 278,

    section CallTarget+Inlining+NGEN
    This PR (6514) - mean (873ms)  : 842, 903
     .   : milestone, 873,
    master - mean (874ms)  : 847, 901
     .   : milestone, 874,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6514) - mean (267ms)  : 262, 271
     .   : milestone, 267,
    master - mean (268ms)  : 264, 272
     .   : milestone, 268,

    section CallTarget+Inlining+NGEN
    This PR (6514) - mean (851ms)  : 813, 889
     .   : milestone, 851,
    master - mean (857ms)  : 829, 885
     .   : milestone, 857,
Loading

@andrewlock
Copy link
Member

Benchmarks Report for tracer 🐌

Benchmarks for #6514 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.183
  • 1 benchmarks are slower, with geometric mean 1.115
  • 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 8.11μs 45.6ns 329ns 0.0166 0.0083 0 5.61 KB
master StartStopWithChild netcoreapp3.1 10.2μs 50ns 320ns 0.0157 0.00524 0 5.8 KB
master StartStopWithChild net472 16.6μs 67.3ns 261ns 1.06 0.331 0.0889 6.21 KB
#6514 StartStopWithChild net6.0 7.9μs 44.3ns 287ns 0.0121 0.00403 0 5.62 KB
#6514 StartStopWithChild netcoreapp3.1 10.2μs 57.8ns 413ns 0.0199 0.00994 0 5.8 KB
#6514 StartStopWithChild net472 16.4μs 28.8ns 112ns 1.04 0.289 0.0964 6.22 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 480μs 324ns 1.26μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 654μs 328ns 1.18μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 855μs 841ns 3.26μs 0.422 0 0 3.3 KB
#6514 WriteAndFlushEnrichedTraces net6.0 520μs 278ns 1.08μs 0 0 0 2.7 KB
#6514 WriteAndFlushEnrichedTraces netcoreapp3.1 654μs 585ns 2.19μs 0 0 0 2.7 KB
#6514 WriteAndFlushEnrichedTraces net472 856μs 767ns 2.97μs 0.422 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 156μs 957ns 9.52μs 0.152 0 0 14.47 KB
master SendRequest netcoreapp3.1 172μs 1.01μs 9.35μs 0.165 0 0 17.27 KB
master SendRequest net472 0.00178ns 0.000725ns 0.00281ns 0 0 0 0 b
#6514 SendRequest net6.0 154μs 1.03μs 10.1μs 0.147 0 0 14.47 KB
#6514 SendRequest netcoreapp3.1 175μs 1.03μs 9.79μs 0.166 0 0 17.27 KB
#6514 SendRequest net472 0.00574ns 0.00158ns 0.00613ns 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 581μs 3.27μs 22μs 0.587 0 0 41.6 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 671μs 3.72μs 22μs 0.322 0 0 41.7 KB
master WriteAndFlushEnrichedTraces net472 867μs 3.9μs 15.1μs 8.19 2.59 0.431 53.33 KB
#6514 WriteAndFlushEnrichedTraces net6.0 553μs 2.84μs 14.2μs 0.553 0 0 41.5 KB
#6514 WriteAndFlushEnrichedTraces netcoreapp3.1 700μs 5.29μs 52.7μs 0.327 0 0 41.79 KB
#6514 WriteAndFlushEnrichedTraces net472 827μs 2.84μs 11μs 8.19 2.59 0.431 53.29 KB
Benchmarks.Trace.DbCommandBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6514

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.DbCommandBenchmark.ExecuteNonQuery‑net6.0 1.115 1,294.96 1,444.17

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.29μs 1.29ns 4.84ns 0.014 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.8μs 1.33ns 4.97ns 0.0135 0 0 1.02 KB
master ExecuteNonQuery net472 2.13μs 2.18ns 8.44ns 0.157 0.00106 0 987 B
#6514 ExecuteNonQuery net6.0 1.44μs 2.75ns 10.6ns 0.0143 0 0 1.02 KB
#6514 ExecuteNonQuery netcoreapp3.1 1.78μs 2.72ns 10.5ns 0.0133 0 0 1.02 KB
#6514 ExecuteNonQuery net472 2.08μs 3.22ns 12.5ns 0.156 0.00101 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.16μs 0.665ns 2.49ns 0.0139 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.54μs 1.66ns 6.21ns 0.0132 0 0 976 B
master CallElasticsearch net472 2.53μs 2.45ns 9.16ns 0.158 0 0 995 B
master CallElasticsearchAsync net6.0 1.23μs 0.618ns 2.31ns 0.013 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.69μs 0.65ns 2.43ns 0.0136 0 0 1.02 KB
master CallElasticsearchAsync net472 2.68μs 1.79ns 6.94ns 0.167 0 0 1.05 KB
#6514 CallElasticsearch net6.0 1.24μs 0.839ns 3.25ns 0.0138 0 0 976 B
#6514 CallElasticsearch netcoreapp3.1 1.46μs 1.08ns 3.75ns 0.0131 0 0 976 B
#6514 CallElasticsearch net472 2.48μs 2.11ns 7.89ns 0.158 0 0 995 B
#6514 CallElasticsearchAsync net6.0 1.25μs 1.35ns 5.03ns 0.0131 0 0 952 B
#6514 CallElasticsearchAsync netcoreapp3.1 1.67μs 1.09ns 4.07ns 0.0133 0 0 1.02 KB
#6514 CallElasticsearchAsync net472 2.67μs 1.87ns 7.25ns 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.864ns 3.23ns 0.0134 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.65μs 0.581ns 2.18ns 0.0124 0 0 952 B
master ExecuteAsync net472 1.82μs 1.09ns 3.78ns 0.145 0 0 915 B
#6514 ExecuteAsync net6.0 1.23μs 1.13ns 4.22ns 0.0134 0 0 952 B
#6514 ExecuteAsync netcoreapp3.1 1.62μs 0.47ns 1.69ns 0.013 0 0 952 B
#6514 ExecuteAsync net472 1.78μs 0.33ns 1.24ns 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.45μs 1.73ns 6.68ns 0.0315 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.29μs 2.82ns 10.9ns 0.0371 0 0 2.85 KB
master SendAsync net472 7.36μs 3.05ns 11ns 0.494 0 0 3.12 KB
#6514 SendAsync net6.0 4.53μs 1.78ns 6.68ns 0.0318 0 0 2.31 KB
#6514 SendAsync netcoreapp3.1 5.33μs 2.39ns 9.25ns 0.0373 0 0 2.85 KB
#6514 SendAsync net472 7.4μs 1.55ns 6.02ns 0.492 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.54μs 0.653ns 2.45ns 0.0231 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.09μs 0.997ns 3.73ns 0.0225 0 0 1.64 KB
master EnrichedLog net472 2.69μs 2.29ns 8.57ns 0.249 0 0 1.57 KB
#6514 EnrichedLog net6.0 1.54μs 0.765ns 2.86ns 0.0234 0 0 1.64 KB
#6514 EnrichedLog netcoreapp3.1 2.22μs 1.02ns 3.83ns 0.0222 0 0 1.64 KB
#6514 EnrichedLog net472 2.69μs 2.6ns 10.1ns 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 118μs 195ns 756ns 0 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 120μs 164ns 635ns 0.0603 0 0 4.28 KB
master EnrichedLog net472 151μs 173ns 648ns 0.671 0.224 0 4.46 KB
#6514 EnrichedLog net6.0 119μs 268ns 1.04μs 0.0591 0 0 4.28 KB
#6514 EnrichedLog netcoreapp3.1 123μs 109ns 407ns 0 0 0 4.28 KB
#6514 EnrichedLog net472 151μs 209ns 808ns 0.679 0.226 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.92μs 1.13ns 4.38ns 0.0306 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.2μs 1.84ns 6.88ns 0.0294 0 0 2.2 KB
master EnrichedLog net472 4.88μs 1.69ns 6.54ns 0.319 0 0 2.02 KB
#6514 EnrichedLog net6.0 2.98μs 0.847ns 3.28ns 0.03 0 0 2.2 KB
#6514 EnrichedLog netcoreapp3.1 4.26μs 1.49ns 5.78ns 0.0295 0 0 2.2 KB
#6514 EnrichedLog net472 5μs 2.16ns 8.36ns 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.41μs 0.818ns 3.17ns 0.0162 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.76μs 0.633ns 2.28ns 0.0152 0 0 1.14 KB
master SendReceive net472 2.13μs 1.58ns 5.92ns 0.184 0 0 1.16 KB
#6514 SendReceive net6.0 1.46μs 1.31ns 5.07ns 0.0162 0 0 1.14 KB
#6514 SendReceive netcoreapp3.1 1.76μs 1.26ns 4.87ns 0.0149 0 0 1.14 KB
#6514 SendReceive net472 2.17μs 1.68ns 6.52ns 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.881ns 3.3ns 0.0223 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.95μs 1.6ns 6.19ns 0.0219 0 0 1.65 KB
master EnrichedLog net472 4.24μs 3.28ns 11.8ns 0.322 0 0 2.04 KB
#6514 EnrichedLog net6.0 2.58μs 1.16ns 4.5ns 0.022 0 0 1.6 KB
#6514 EnrichedLog netcoreapp3.1 3.94μs 2.57ns 9.61ns 0.0216 0 0 1.65 KB
#6514 EnrichedLog net472 4.38μs 2.74ns 10.6ns 0.322 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #6514

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 1.183 562.66 475.49

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 402ns 0.511ns 1.98ns 0.0081 0 0 576 B
master StartFinishSpan netcoreapp3.1 539ns 0.687ns 2.66ns 0.00777 0 0 576 B
master StartFinishSpan net472 650ns 1.43ns 5.56ns 0.0917 0 0 578 B
master StartFinishScope net6.0 563ns 0.836ns 3.24ns 0.00971 0 0 696 B
master StartFinishScope netcoreapp3.1 713ns 1.11ns 4.31ns 0.00965 0 0 696 B
master StartFinishScope net472 885ns 1.17ns 4.53ns 0.104 0 0 658 B
#6514 StartFinishSpan net6.0 395ns 0.469ns 1.82ns 0.0081 0 0 576 B
#6514 StartFinishSpan netcoreapp3.1 573ns 2.82ns 11.3ns 0.00771 0 0 576 B
#6514 StartFinishSpan net472 642ns 0.73ns 2.83ns 0.0916 0 0 578 B
#6514 StartFinishScope net6.0 475ns 1.22ns 4.57ns 0.00976 0 0 696 B
#6514 StartFinishScope netcoreapp3.1 689ns 1.45ns 5.62ns 0.00924 0 0 696 B
#6514 StartFinishScope net472 888ns 1.82ns 7.05ns 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 600ns 1.14ns 4.4ns 0.00973 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 896ns 1.28ns 4.96ns 0.00933 0 0 696 B
master RunOnMethodBegin net472 1.09μs 1.93ns 7.46ns 0.104 0 0 658 B
#6514 RunOnMethodBegin net6.0 619ns 0.632ns 2.45ns 0.00971 0 0 696 B
#6514 RunOnMethodBegin netcoreapp3.1 929ns 1.22ns 4.74ns 0.00911 0 0 696 B
#6514 RunOnMethodBegin net472 1.07μs 0.669ns 2.5ns 0.104 0 0 658 B

@kevingosse kevingosse merged commit 48b0333 into master Jan 9, 2025
100 of 102 checks passed
@kevingosse kevingosse deleted the kevin/fix_telemetry_test branch January 9, 2025 11:08
@github-actions github-actions bot added this to the vNext-v3 milestone Jan 9, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@andrewlock andrewlock andrewlock approved these changes

Assignees
No one assigned
Labels
area:tests unit tests, integration tests
Projects
None yet
Milestone
vNext-v3
Development

Successfully merging this pull request may close these issues.
2 participants
@kevingosse @andrewlock