Skip to content

Un-skip manual instrumentation tests and fix flake#4960

Merged
andrewlock merged 1 commit into
masterfrom
andrew/workaround-manual-flake
Dec 13, 2023
Merged

Un-skip manual instrumentation tests and fix flake#4960
andrewlock merged 1 commit into
masterfrom
andrew/workaround-manual-flake

Conversation

@andrewlock

@andrewlock andrewlock commented Dec 7, 2023

Copy link
Copy Markdown
Member

Summary of changes

  • Add workaround for manual-instrumentation test flake
  • Unskip the manual instrumentation tests

Reason for change

#4938 introduced integration tests for manual and manual+automatic instrumentation. Unfortunately, we had to skip them in #4949 because they were flaky. This PR removes the flake, and so unskips the tests.

Implementation details

This PR doesn't resolve the underlying issue, it just removes the flake from the test.

The underlying cause of the flake is:

  • Serialized spans have a TraceContext, which contains a reference to a Tracer instance
  • During serialization, a TraceChunkModel is created, which records (among other things) the DefaultServiceName by calling spans[0].TraceContext.Tracer.DefaultServiceName
  • The span formatter code uses the DefaultServiceName to decide whether to add the version tag (it should currently only be added to spans for which service == DefaultServiceName).

The trouble is that in normal operation, TraceContext.Tracer.DefaultServiceName doesn't necessarily point to the DefaultServiceName at the time the span was serialized. Rather, it points to the current TracerManager instance.

In the integration tests, we were reconfiguring the tracer multiple times, so there was a high chance that the TracerManager used to create the spans was different to the current global TracerManager when that span was serialized in the background, which in turn meant the service version tag might not be added.

The "fix" in the integration tests is to simply not set the service version. If there's no version to add, there's no chance of flake. Obviously this doesn't fix the underlying issue, but the solution to the underlying problem isn't entirely obvious, could be breaking depend on how we decide to do it, and should be uncommon in normal customer usage

Test coverage

Unskipped some integration tests, and updated the snapshots to remove the version tags.

Other details

I wanted to get these running again because we need them for the v3 work.

@andrewlock andrewlock added area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) area:tests unit tests, integration tests labels Dec 7, 2023
@andrewlock
andrewlock requested a review from a team as a code owner December 7, 2023 12:00
@github-actions

github-actions Bot commented Dec 7, 2023

Copy link
Copy Markdown
Contributor

Snapshots difference summary

The following differences have been observed in committed snapshots. It is meant to help the reviewer.
The diff is simplistic, so please check some files anyway while we improve it.

6 occurrences of :

-      version: updated-version,

@datadog-ddstaging

datadog-ddstaging Bot commented Dec 7, 2023 •
edited
Loading

Copy link
Copy Markdown

Datadog Report

Branch report: andrew/workaround-manual-flake
Commit report: 9d09e20

✅ dd-trace-dotnet: 0 Failed, 0 New Flaky, 303429 Passed, 993 Skipped, 30m 23.89s Wall Time

@andrewlock

andrewlock commented Dec 7, 2023

Copy link
Copy Markdown
Member Author

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 (4960) - mean (70ms)  : 63, 77
     .   : milestone, 70,
    master - mean (71ms)  : 61, 81
     .   : milestone, 71,

    section CallTarget+Inlining+NGEN
    This PR (4960) - mean (1,004ms)  : 984, 1025
     .   : milestone, 1004,
    master - mean (995ms)  : 973, 1018
     .   : milestone, 995,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4960) - mean (106ms)  : 103, 109
     .   : milestone, 106,
    master - mean (105ms)  : 102, 109
     .   : milestone, 105,

    section CallTarget+Inlining+NGEN
    This PR (4960) - mean (694ms)  : 682, 707
     .   : milestone, 694,
    master - mean (690ms)  : 666, 713
     .   : milestone, 690,
Loading 
gantt
    title Execution time (ms) FakeDbCommand (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4960) - mean (89ms)  : 87, 92
     .   : milestone, 89,
    master - mean (89ms)  : 85, 94
     .   : milestone, 89,

    section CallTarget+Inlining+NGEN
    This PR (4960) - mean (664ms)  : 641, 687
     .   : milestone, 664,
    master - mean (659ms)  : 632, 686
     .   : milestone, 659,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4960) - mean (190ms)  : 187, 193
     .   : milestone, 190,
    master - mean (190ms)  : 187, 193
     .   : milestone, 190,

    section CallTarget+Inlining+NGEN
    This PR (4960) - mean (1,143ms)  : 1122, 1163
     .   : milestone, 1143,
    master - mean (1,144ms)  : 1123, 1164
     .   : milestone, 1144,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4960) - mean (274ms)  : 271, 277
     .   : milestone, 274,
    master - mean (274ms)  : 270, 278
     .   : milestone, 274,

    section CallTarget+Inlining+NGEN
    This PR (4960) - mean (1,098ms)  : 1077, 1119
     .   : milestone, 1098,
    master - mean (1,099ms)  : 1076, 1122
     .   : milestone, 1099,
Loading 
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (4960) - mean (263ms)  : 259, 266
     .   : milestone, 263,
    master - mean (263ms)  : 260, 266
     .   : milestone, 263,

    section CallTarget+Inlining+NGEN
    This PR (4960) - mean (1,061ms)  : 1030, 1093
     .   : milestone, 1061,
    master - mean (1,061ms)  : 1036, 1086
     .   : milestone, 1061,
Loading

@andrewlock

andrewlock commented Dec 7, 2023

Copy link
Copy Markdown
Member Author

Throughput/Crank Report:zap:

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 (4960) (11.700M)   : 0, 11699742
    master (11.526M)   : 0, 11525554
    benchmarks/2.9.0 (11.237M)   : 0, 11237241

    section Automatic
    This PR (4960) (7.983M)   : 0, 7983388
    master (7.877M)   : 0, 7877297
    benchmarks/2.9.0 (7.840M)   : 0, 7840137

    section Trace stats
    This PR (4960) (8.222M)   : 0, 8221885
    master (8.231M)   : 0, 8231421

    section Manual
    This PR (4960) (10.137M)   : 0, 10137100
    master (10.054M)   : 0, 10053936

    section Manual + Automatic
    This PR (4960) (7.411M)   : 0, 7410560
    master (7.428M)   : 0, 7428363

    section Version Conflict
    This PR (4960) (6.697M)   : 0, 6697163
    master (6.727M)   : 0, 6727014
Loading 
gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4960) (9.248M)   : 0, 9247894
    master (9.405M)   : 0, 9404738
    benchmarks/2.9.0 (9.665M)   : 0, 9664612

    section Automatic
    This PR (4960) (6.501M)   : 0, 6500524
    master (6.577M)   : 0, 6577406

    section Trace stats
    This PR (4960) (6.897M)   : 0, 6896607
    master (6.810M)   : 0, 6810193

    section Manual
    This PR (4960) (7.986M)   : 0, 7986371
    master (8.022M)   : 0, 8021804

    section Manual + Automatic
    This PR (4960) (6.100M)   : 0, 6099675
    master (6.110M)   : 0, 6109763

    section Version Conflict
    This PR (4960) (5.760M)   : 0, 5760117
    master (5.746M)   : 0, 5745979
Loading 
gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (4960) (10.599M)   : 0, 10599010
    master (10.466M)   : 0, 10465899
    benchmarks/2.9.0 (10.237M)   : 0, 10237432

    section Automatic
    This PR (4960) (7.526M)   : 0, 7526000
    master (7.486M)   : 0, 7485516
    benchmarks/2.9.0 (7.647M)   : 0, 7647424

    section Trace stats
    This PR (4960) (7.862M)   : 0, 7862038
    master (7.809M)   : 0, 7808848

    section Manual
    This PR (4960) (8.855M)   : 0, 8854834
    master (9.257M)   : 0, 9257200

    section Manual + Automatic
    This PR (4960) (7.078M)   : 0, 7077889
    master (7.255M)   : 0, 7255413

    section Version Conflict
    This PR (4960) (6.495M)   : 0, 6495010
    master (6.708M)   : 0, 6708396
Loading 
gantt
    title Throughput Linux x64 (ASM) (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    master (7.655M)   : 0, 7654796
    benchmarks/2.9.0 (7.884M)   : 0, 7884497

    section No attack
    master (2.066M)   : 0, 2066290
    benchmarks/2.9.0 (3.271M)   : 0, 3270642

    section Attack
    master (1.638M)   : 0, 1637602
    benchmarks/2.9.0 (2.628M)   : 0, 2627789

    section Blocking
    master (3.377M)   : 0, 3376827

    section IAST default
    master (6.744M)   : 0, 6744105

    section IAST full
    master (6.038M)   : 0, 6037702

    section Base vuln
    master (1.005M)   : 0, 1004747

    section IAST vuln
    master (0.887M)   : 0, 887064
Loading

@andrewlock

andrewlock commented Dec 7, 2023

Copy link
Copy Markdown
Member Author

Benchmarks Report 🐌

Benchmarks for #4960 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.342
  • 5 benchmarks are slower, with geometric mean 1.180
  • 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.5μs 47.1ns 282ns 0.0215 0.00862 0 7.48 KB
master StartStopWithChild netcoreapp3.1 10.8μs 56.4ns 288ns 0.0432 0.0216 0.0054 7.57 KB
master StartStopWithChild net472 16.8μs 36.9ns 143ns 1.32 0.321 0.0905 7.95 KB
#4960 StartStopWithChild net6.0 8.37μs 45.9ns 286ns 0.0249 0.00829 0 7.48 KB
#4960 StartStopWithChild netcoreapp3.1 10.6μs 54.7ns 268ns 0.0252 0.0101 0 7.57 KB
#4960 StartStopWithChild net472 16.9μs 62.6ns 243ns 1.33 0.342 0.117 7.96 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 488μs 132ns 495ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 616μs 245ns 948ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 786μs 316ns 1.14μs 0.391 0 0 3.3 KB
#4960 WriteAndFlushEnrichedTraces net6.0 466μs 301ns 1.17μs 0 0 0 2.7 KB
#4960 WriteAndFlushEnrichedTraces netcoreapp3.1 634μs 267ns 1.03μs 0 0 0 2.7 KB
#4960 WriteAndFlushEnrichedTraces net472 782μs 348ns 1.3μs 0.388 0 0 3.3 KB
Benchmarks.Trace.Asm.AppSecBodyBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #4960

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.Asm.AppSecBodyBenchmark.ObjectExtractorSimpleBody‑netcoreapp3.1 1.252 179.75 224.98

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master AllCycleSimpleBody net6.0 43.6μs 15.6ns 60.6ns 0.0221 0 0 1.77 KB
master AllCycleSimpleBody netcoreapp3.1 46.6μs 52.8ns 205ns 0.0232 0 0 1.74 KB
master AllCycleSimpleBody net472 48.6μs 58.7ns 227ns 0.266 0 0 1.81 KB
master AllCycleMoreComplexBody net6.0 216μs 64.6ns 250ns 0.108 0 0 9.25 KB
master AllCycleMoreComplexBody netcoreapp3.1 225μs 374ns 1.45μs 0.113 0 0 9.14 KB
master AllCycleMoreComplexBody net472 239μs 241ns 934ns 1.43 0 0 9.32 KB
master ObjectExtractorSimpleBody net6.0 134ns 0.0228ns 0.0823ns 0.00393 0 0 280 B
master ObjectExtractorSimpleBody netcoreapp3.1 180ns 0.0677ns 0.253ns 0.00374 0 0 272 B
master ObjectExtractorSimpleBody net472 152ns 0.0955ns 0.37ns 0.0446 0 0 281 B
master ObjectExtractorMoreComplexBody net6.0 2.9μs 1.37ns 6.87ns 0.0535 0 0 3.78 KB
master ObjectExtractorMoreComplexBody netcoreapp3.1 3.8μs 1.01ns 3.79ns 0.0493 0 0 3.69 KB
master ObjectExtractorMoreComplexBody net472 3.41μs 1.39ns 5.37ns 0.602 0.00513 0 3.8 KB
#4960 AllCycleSimpleBody net6.0 44.7μs 34.2ns 123ns 0.0221 0 0 1.77 KB
#4960 AllCycleSimpleBody netcoreapp3.1 46.8μs 63.2ns 245ns 0.0233 0 0 1.74 KB
#4960 AllCycleSimpleBody net472 50μs 17.1ns 66.3ns 0.274 0 0 1.81 KB
#4960 AllCycleMoreComplexBody net6.0 213μs 120ns 448ns 0.107 0 0 9.25 KB
#4960 AllCycleMoreComplexBody netcoreapp3.1 226μs 370ns 1.43μs 0.113 0 0 9.14 KB
#4960 AllCycleMoreComplexBody net472 239μs 94.7ns 328ns 1.43 0 0 9.32 KB
#4960 ObjectExtractorSimpleBody net6.0 134ns 0.0377ns 0.146ns 0.00393 0 0 280 B
#4960 ObjectExtractorSimpleBody netcoreapp3.1 226ns 0.775ns 3ns 0.00373 0 0 272 B
#4960 ObjectExtractorSimpleBody net472 152ns 0.0853ns 0.33ns 0.0446 0 0 281 B
#4960 ObjectExtractorMoreComplexBody net6.0 2.82μs 0.703ns 2.53ns 0.0526 0 0 3.78 KB
#4960 ObjectExtractorMoreComplexBody netcoreapp3.1 3.62μs 1.27ns 4.92ns 0.0493 0 0 3.69 KB
#4960 ObjectExtractorMoreComplexBody net472 3.44μs 1.82ns 7.03ns 0.603 0.00517 0 3.8 KB
Benchmarks.Trace.Asm.AppSecWafBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunWaf(args=NestedMap (10)) net6.0 49μs 19.6ns 73.2ns 0.22 0 0 16.06 KB
master RunWaf(args=NestedMap (10)) netcoreapp3.1 64.6μs 289ns 1.04μs 0.192 0 0 16.06 KB
master RunWaf(args=NestedMap (10)) net472 96μs 479ns 2.03μs 2.54 0.0941 0 16.14 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 116μs 27.1ns 101ns 0.289 0 0 22.41 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 137μs 184ns 714ns 0.28 0 0 22.36 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net472 168μs 178ns 688ns 3.58 0.17 0 22.7 KB
master RunWaf(args=NestedMap (100)) net6.0 98.1μs 567ns 4.61μs 0.428 0 0 32.76 KB
master RunWaf(args=NestedMap (100)) netcoreapp3.1 134μs 646ns 2.74μs 0.399 0 0 33.33 KB
master RunWaf(args=NestedMap (100)) net472 182μs 124ns 481ns 5.32 0.367 0 33.67 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) net6.0 164μs 61.5ns 238ns 0.499 0 0 39.1 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) netcoreapp3.1 208μs 996ns 4.88μs 0.529 0 0 39.63 KB
master RunWafWithAttack(args=Neste(...)tack) [23]) net472 260μs 154ns 575ns 6.34 0.518 0 40.23 KB
master RunWaf(args=NestedMap (20)) net6.0 97.3μs 530ns 2.9μs 0.452 0 0 32.18 KB
master RunWaf(args=NestedMap (20)) netcoreapp3.1 133μs 687ns 3.5μs 0.431 0 0 32.3 KB
master RunWaf(args=NestedMap (20)) net472 181μs 158ns 612ns 5.16 0.362 0 32.63 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 174μs 831ns 3.22μs 0.495 0 0 38.53 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 205μs 647ns 2.51μs 0.501 0 0 38.6 KB
master RunWafWithAttack(args=Neste(...)tack) [22]) net472 261μs 125ns 469ns 6.22 0.519 0 39.2 KB
#4960 RunWaf(args=NestedMap (10)) net6.0 52.6μs 343ns 3.43μs 0.212 0 0 16.06 KB
#4960 RunWaf(args=NestedMap (10)) netcoreapp3.1 68.3μs 370ns 2.09μs 0.209 0 0 16.06 KB
#4960 RunWaf(args=NestedMap (10)) net472 93.6μs 36.1ns 140ns 2.53 0.0936 0 16.14 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 116μs 94.1ns 365ns 0.305 0 0 22.41 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 138μs 399ns 1.55μs 0.267 0 0 22.36 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [22]) net472 165μs 58.6ns 211ns 3.59 0.167 0 22.7 KB
#4960 RunWaf(args=NestedMap (100)) net6.0 104μs 558ns 2.95μs 0.423 0 0 32.76 KB
#4960 RunWaf(args=NestedMap (100)) netcoreapp3.1 133μs 39.3ns 136ns 0.4 0 0 33.33 KB
#4960 RunWaf(args=NestedMap (100)) net472 182μs 87.7ns 340ns 5.29 0.365 0 33.67 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [23]) net6.0 180μs 65.9ns 238ns 0.513 0 0 39.1 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [23]) netcoreapp3.1 210μs 344ns 1.29μs 0.523 0 0 39.63 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [23]) net472 260μs 72.1ns 270ns 6.34 0.518 0 40.23 KB
#4960 RunWaf(args=NestedMap (20)) net6.0 107μs 84.8ns 328ns 0.43 0 0 32.18 KB
#4960 RunWaf(args=NestedMap (20)) netcoreapp3.1 131μs 716ns 4.42μs 0.382 0 0 32.3 KB
#4960 RunWaf(args=NestedMap (20)) net472 181μs 131ns 505ns 5.14 0.361 0 32.63 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [22]) net6.0 169μs 145ns 542ns 0.497 0 0 38.53 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [22]) netcoreapp3.1 205μs 623ns 2.41μs 0.503 0 0 38.6 KB
#4960 RunWafWithAttack(args=Neste(...)tack) [22]) net472 266μs 1.19μs 4.59μs 6.22 0.519 0 39.2 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 172μs 143ns 514ns 0.261 0 0 18.25 KB
master SendRequest netcoreapp3.1 193μs 393ns 1.52μs 0.193 0 0 20.41 KB
master SendRequest net472 8.74E‑05ns 8.74E‑05ns 0.000327ns 0 0 0 0 b
#4960 SendRequest net6.0 173μs 174ns 673ns 0.258 0 0 18.25 KB
#4960 SendRequest netcoreapp3.1 193μs 334ns 1.3μs 0.191 0 0 20.41 KB
#4960 SendRequest net472 9.83E‑06ns 9.83E‑06ns 3.54E‑05ns 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 550μs 190ns 685ns 0.548 0 0 41.63 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 666μs 1.17μs 4.52μs 0.331 0 0 41.73 KB
master WriteAndFlushEnrichedTraces net472 833μs 2.82μs 10.6μs 8.33 2.5 0.417 53.2 KB
#4960 WriteAndFlushEnrichedTraces net6.0 548μs 1.42μs 5.52μs 0.543 0 0 41.62 KB
#4960 WriteAndFlushEnrichedTraces netcoreapp3.1 657μs 412ns 1.59μs 0.326 0 0 41.61 KB
#4960 WriteAndFlushEnrichedTraces net472 831μs 3.94μs 16.2μs 8.28 2.48 0.414 53.22 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.05μs 0.326ns 1.26ns 0.0106 0 0 768 B
master ExecuteNonQuery netcoreapp3.1 1.4μs 0.332ns 1.24ns 0.0105 0 0 768 B
master ExecuteNonQuery net472 1.8μs 0.545ns 2.11ns 0.116 0 0 730 B
#4960 ExecuteNonQuery net6.0 1.07μs 0.428ns 1.66ns 0.0106 0 0 768 B
#4960 ExecuteNonQuery netcoreapp3.1 1.46μs 0.598ns 2.32ns 0.0103 0 0 768 B
#4960 ExecuteNonQuery net472 1.78μs 0.325ns 1.17ns 0.115 0 0 730 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.25μs 0.615ns 2.3ns 0.0132 0 0 936 B
master CallElasticsearch netcoreapp3.1 1.52μs 0.622ns 2.33ns 0.0129 0 0 936 B
master CallElasticsearch net472 2.44μs 0.875ns 3.39ns 0.151 0 0 955 B
master CallElasticsearchAsync net6.0 1.3μs 0.726ns 2.81ns 0.0124 0 0 912 B
master CallElasticsearchAsync netcoreapp3.1 1.62μs 0.402ns 1.45ns 0.013 0 0 984 B
master CallElasticsearchAsync net472 2.57μs 1.5ns 5.82ns 0.16 0 0 1.01 KB
#4960 CallElasticsearch net6.0 1.23μs 0.669ns 2.5ns 0.013 0 0 936 B
#4960 CallElasticsearch netcoreapp3.1 1.58μs 1.84ns 7.14ns 0.0128 0 0 936 B
#4960 CallElasticsearch net472 2.54μs 0.78ns 3.02ns 0.151 0 0 955 B
#4960 CallElasticsearchAsync net6.0 1.33μs 0.486ns 1.82ns 0.0125 0 0 912 B
#4960 CallElasticsearchAsync netcoreapp3.1 1.6μs 1.01ns 3.9ns 0.0127 0 0 984 B
#4960 CallElasticsearchAsync net472 2.7μs 0.877ns 3.28ns 0.16 0 0 1.01 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.31μs 1.05ns 4.08ns 0.0125 0 0 912 B
master ExecuteAsync netcoreapp3.1 1.61μs 0.82ns 3.18ns 0.0124 0 0 912 B
master ExecuteAsync net472 1.82μs 1.65ns 6.17ns 0.138 0.000911 0 875 B
#4960 ExecuteAsync net6.0 1.31μs 1.39ns 5.21ns 0.0131 0 0 912 B
#4960 ExecuteAsync netcoreapp3.1 1.68μs 0.675ns 2.53ns 0.0116 0 0 912 B
#4960 ExecuteAsync net472 1.81μs 2.1ns 7.86ns 0.139 0.000896 0 875 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 3.86μs 1.93ns 7.22ns 0.0289 0 0 2.1 KB
master SendAsync netcoreapp3.1 4.81μs 2.48ns 9.61ns 0.036 0 0 2.63 KB
master SendAsync net472 7.87μs 4.83ns 18.1ns 0.524 0 0 3.31 KB
#4960 SendAsync net6.0 4.06μs 2.68ns 10.4ns 0.0286 0 0 2.1 KB
#4960 SendAsync netcoreapp3.1 5.02μs 4.37ns 16.4ns 0.0355 0 0 2.63 KB
#4960 SendAsync net472 7.9μs 4.22ns 16.4ns 0.522 0 0 3.31 KB
Benchmarks.Trace.Iast.StringAspectsBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #4960

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark(parameters: System.Collections.Generic.List`1[System.String])‑netcoreapp3.1 1.176 53,500.00 62,900.00 multimodal

Faster 🎉 in #4960

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatAspectBenchmark(parameters: System.Collections.Generic.List`1[System.String])‑net6.0 1.540 101,200.00 65,700.00 multimodal
Benchmarks.Trace.Iast.StringAspectsBenchmark.StringConcatBenchmark(parameters: System.Collections.Generic.List`1[System.String])‑net6.0 1.170 62,000.00 53,000.00 bimodal

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StringConcatBenchmark(parameters=Syste(...)ring] [48]) net6.0 64μs 779ns 7.79μs 0 0 0 43.44 KB
master StringConcatBenchmark(parameters=Syste(...)ring] [48]) netcoreapp3.1 53.4μs 184ns 687ns 0 0 0 42.64 KB
master StringConcatBenchmark(parameters=Syste(...)ring] [48]) net472 37.7μs 58.2ns 210ns 0 0 0 59.66 KB
master StringConcatAspectBenchmark(parameters=Syste(...)ring] [48]) net6.0 106μs 2.69μs 26.9μs 0 0 0 43.29 KB
master StringConcatAspectBenchmark(parameters=Syste(...)ring] [48]) netcoreapp3.1 119μs 2.44μs 24.4μs 0 0 0 42.64 KB
master StringConcatAspectBenchmark(parameters=Syste(...)ring] [48]) net472 63.9μs 230ns 796ns 0 0 0 57.34 KB
#4960 StringConcatBenchmark(parameters=Syste(...)ring] [48]) net6.0 53μs 221ns 938ns 0 0 0 43.44 KB
#4960 StringConcatBenchmark(parameters=Syste(...)ring] [48]) netcoreapp3.1 64.8μs 927ns 9.27μs 0 0 0 42.64 KB
#4960 StringConcatBenchmark(parameters=Syste(...)ring] [48]) net472 37.9μs 173ns 649ns 0 0 0 59.7 KB
#4960 StringConcatAspectBenchmark(parameters=Syste(...)ring] [48]) net6.0 65.4μs 321ns 1.32μs 0 0 0 43.29 KB
#4960 StringConcatAspectBenchmark(parameters=Syste(...)ring] [48]) netcoreapp3.1 111μs 2.67μs 26.7μs 0 0 0 42.64 KB
#4960 StringConcatAspectBenchmark(parameters=Syste(...)ring] [48]) net472 61.4μs 277ns 1.14μs 0 0 0 57.34 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.37μs 0.694ns 2.69ns 0.022 0 0 1.57 KB
master EnrichedLog netcoreapp3.1 2.46μs 1.8ns 6.97ns 0.0211 0 0 1.57 KB
master EnrichedLog net472 2.61μs 1.83ns 7.1ns 0.238 0 0 1.5 KB
#4960 EnrichedLog net6.0 1.52μs 1.61ns 6.22ns 0.0221 0 0 1.57 KB
#4960 EnrichedLog netcoreapp3.1 2.21μs 0.835ns 3.13ns 0.0209 0 0 1.57 KB
#4960 EnrichedLog net472 2.53μs 1.32ns 4.96ns 0.238 0 0 1.5 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 111μs 139ns 538ns 0.0559 0 0 4.21 KB
master EnrichedLog netcoreapp3.1 116μs 70.1ns 272ns 0.0583 0 0 4.21 KB
master EnrichedLog net472 148μs 176ns 683ns 0.669 0.223 0 4.39 KB
#4960 EnrichedLog net6.0 112μs 112ns 433ns 0.0563 0 0 4.21 KB
#4960 EnrichedLog netcoreapp3.1 118μs 94.5ns 353ns 0 0 0 4.21 KB
#4960 EnrichedLog net472 147μs 307ns 1.15μs 0.666 0.222 0 4.39 KB
Benchmarks.Trace.NLogBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #4960

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.NLogBenchmark.EnrichedLog‑net6.0 1.113 2,854.71 3,177.58

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.86μs 1.28ns 4.78ns 0.0292 0 0 2.13 KB
master EnrichedLog netcoreapp3.1 4.13μs 10.2ns 39.3ns 0.0288 0 0 2.13 KB
master EnrichedLog net472 5μs 4.4ns 17ns 0.308 0 0 1.95 KB
#4960 EnrichedLog net6.0 3.18μs 1.08ns 4.19ns 0.0301 0 0 2.13 KB
#4960 EnrichedLog netcoreapp3.1 4.18μs 1.64ns 6.37ns 0.0291 0 0 2.13 KB
#4960 EnrichedLog net472 4.84μs 6.14ns 23.8ns 0.309 0 0 1.95 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.36μs 1.77ns 6.87ns 0.0155 0 0 1.1 KB
master SendReceive netcoreapp3.1 1.74μs 0.488ns 1.89ns 0.0148 0 0 1.1 KB
master SendReceive net472 2.14μs 2.64ns 10.2ns 0.177 0 0 1.12 KB
#4960 SendReceive net6.0 1.3μs 1.13ns 4.38ns 0.015 0 0 1.1 KB
#4960 SendReceive netcoreapp3.1 1.72μs 0.638ns 2.47ns 0.0148 0 0 1.1 KB
#4960 SendReceive net472 2.24μs 2.73ns 10.6ns 0.176 0 0 1.12 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.69μs 0.471ns 1.7ns 0.0215 0 0 1.53 KB
master EnrichedLog netcoreapp3.1 3.84μs 1.34ns 5.21ns 0.0211 0 0 1.58 KB
master EnrichedLog net472 4.41μs 0.453ns 1.69ns 0.312 0 0 1.97 KB
#4960 EnrichedLog net6.0 2.7μs 0.705ns 2.73ns 0.0216 0 0 1.53 KB
#4960 EnrichedLog netcoreapp3.1 3.88μs 1.05ns 4.08ns 0.0213 0 0 1.58 KB
#4960 EnrichedLog net472 4.36μs 1.26ns 4.72ns 0.312 0 0 1.97 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #4960

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑netcoreapp3.1 1.204 781.90 941.43
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 1.160 576.04 668.44

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 537ns 0.143ns 0.535ns 0.00754 0 0 536 B
master StartFinishSpan netcoreapp3.1 758ns 0.924ns 3.33ns 0.00715 0 0 536 B
master StartFinishSpan net472 743ns 0.481ns 1.86ns 0.0852 0 0 538 B
master StartFinishScope net6.0 576ns 0.174ns 0.676ns 0.00901 0 0 656 B
master StartFinishScope netcoreapp3.1 782ns 0.332ns 1.2ns 0.00914 0 0 656 B
master StartFinishScope net472 991ns 0.716ns 2.77ns 0.0978 0 0 618 B
#4960 StartFinishSpan net6.0 534ns 0.166ns 0.599ns 0.00751 0 0 536 B
#4960 StartFinishSpan netcoreapp3.1 740ns 0.684ns 2.65ns 0.00727 0 0 536 B
#4960 StartFinishSpan net472 731ns 0.231ns 0.895ns 0.0852 0 0 538 B
#4960 StartFinishScope net6.0 669ns 0.986ns 3.82ns 0.00904 0 0 656 B
#4960 StartFinishScope netcoreapp3.1 941ns 0.541ns 1.87ns 0.00895 0 0 656 B
#4960 StartFinishScope net472 1.01μs 0.636ns 2.46ns 0.0981 0 0 618 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 617ns 0.317ns 1.23ns 0.00931 0 0 656 B
master RunOnMethodBegin netcoreapp3.1 970ns 0.675ns 2.34ns 0.00877 0 0 656 B
master RunOnMethodBegin net472 1.11μs 0.522ns 2.02ns 0.0981 0 0 618 B
#4960 RunOnMethodBegin net6.0 569ns 0.114ns 0.442ns 0.00924 0 0 656 B
#4960 RunOnMethodBegin netcoreapp3.1 971ns 0.246ns 0.92ns 0.00875 0 0 656 B
#4960 RunOnMethodBegin net472 1.12μs 0.708ns 2.65ns 0.0981 0 0 618 B

@zacharycmontoya

zacharycmontoya commented Dec 12, 2023

Copy link
Copy Markdown
Contributor

I have an idea for a fix in this branch, which copies over the DefaultServiceName when the TraceContext starts. I wonder if we could do this instead of changing our test code.

https://github.com/DataDog/dd-trace-dotnet/tree/zach/default-service-name-fix

@andrewlock

andrewlock commented Dec 13, 2023

Copy link
Copy Markdown
Member Author

I have an idea for a fix in this branch, which copies over the DefaultServiceName when the TraceContext starts.

https://github.com/DataDog/dd-trace-dotnet/tree/zach/default-service-name-fix

Yeah, I, actually took this approach initially as a potential fix, but I'm not sure 😅

  1. It still papers-over the fundamental issue of assuming that Tracer instances behave like instances, and not the global shared singletons they actually behave as
  2. It increases allocations (slightly) for every trace

Given this is a niche issue, I don't know if we want to take the hit from 2? We could "solve" it without increasing allocations by storing a reference to Tracer.TracerManager instead of Tracer, but that may have potential implications we don't want to dive into right now, especially until after v3?

I wonder if we could do this instead of changing our test code.

Personally, my gut feeling was that removing the flake from the test code and un-skipping the tests is the best thing to do right now. It's not entirely clear whether this behaviour is even a "bug" the way things are written. (I mean, it feels like it, but this is "expected behaviour to some extent).

I feel like there's probably a bigger refactoring to be done here, potentially after v3 and after Lucas' SpanContext work, as we may be able to improve things more significantly.

But overall, I'm not sure 🤷

zacharycmontoya
zacharycmontoya approved these changes Dec 13, 2023
View reviewed changes

@zacharycmontoya zacharycmontoya left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

:shipit:

@andrewlock
andrewlock merged commit 01af7e0 into master Dec 13, 2023
@andrewlock
andrewlock deleted the andrew/workaround-manual-flake branch December 13, 2023 18:22
@github-actions github-actions Bot added this to the vNext milestone Dec 13, 2023
@andrewlock andrewlock mentioned this pull request Nov 21, 2024
Merged
andrewlock added a commit that referenced this pull request Nov 25, 2024
@andrewlock
Try to fix flake in ManualInstrumentation tests (#6333)
467825f 
## Summary of changes

Add a mutex to try to avoid flake

## Reason for change

We see occasional flake in the manual + automatic instrumentation tests.
I don't entirely understand why this happens _other than_ it shows that
the httplistener span is getting serialized _after_ we have reconfigured
the tracer (because traces _aren't_ tied to a settings instance). This
is arguably a bug, but it's "known" to an extent. The problem is that
it's causing flake when you change the base service name.

> FWIW, we already "fixed" this same symptom once:
#4960


## Implementation details

Add a mutex to try to make sure the httplistener span is closed before
we close the request span

## Test coverage

Enabled debug logs so that we can get more details if this _does_ recur.

## Other details

Stacked on:
- #6330
veerbia pushed a commit that referenced this pull request Dec 16, 2024
@andrewlock @veerbia
Try to fix flake in ManualInstrumentation tests (#6333)
43da117 
## Summary of changes

Add a mutex to try to avoid flake

## Reason for change

We see occasional flake in the manual + automatic instrumentation tests.
I don't entirely understand why this happens _other than_ it shows that
the httplistener span is getting serialized _after_ we have reconfigured
the tracer (because traces _aren't_ tied to a settings instance). This
is arguably a bug, but it's "known" to an extent. The problem is that
it's causing flake when you change the base service name.

> FWIW, we already "fixed" this same symptom once:
#4960


## Implementation details

Add a mutex to try to make sure the httplistener span is closed before
we close the request span

## Test coverage

Enabled debug logs so that we can get more details if this _does_ recur.

## Other details

Stacked on:
- #6330
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@lucaspimentel lucaspimentel lucaspimentel approved these changes
@zacharycmontoya zacharycmontoya zacharycmontoya approved these changes
@pierotibou pierotibou pierotibou approved these changes

Assignees

No one assigned

Labels

area:tests unit tests, integration tests area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations)

Projects

None yet

Milestone

2.44.0

Development

Successfully merging this pull request may close these issues.

4 participants

@andrewlock @zacharycmontoya @lucaspimentel @pierotibou