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

[Profiler] Update tests to save output to xunit.txt files #6160

Merged
merged 13 commits into from
Nov 25, 2024

Conversation

chrisnas
Copy link
Contributor

Summary of changes

Update all tests to send output to console AND file

Reason for change

That way, it is possible to have the tests output visible in the CI with xunit.txt file to download

Implementation details

Update all tests

Test coverage

n/a

Other details

@chrisnas chrisnas requested a review from a team as a code owner October 16, 2024 09:43
@github-actions github-actions bot added the area:profiler Issues related to the continous-profiler label Oct 16, 2024
@andrewlock
Copy link
Member

andrewlock commented Oct 16, 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 (6160) - mean (72ms)  : 62, 82
     .   : milestone, 72,
    master - mean (72ms)  : 64, 80
     .   : milestone, 72,

    section CallTarget+Inlining+NGEN
    This PR (6160) - mean (987ms)  : 963, 1012
     .   : milestone, 987,
    master - mean (987ms)  : 959, 1014
     .   : milestone, 987,

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

    section CallTarget+Inlining+NGEN
    This PR (6160) - mean (687ms)  : 673, 701
     .   : milestone, 687,
    master - mean (684ms)  : 665, 703
     .   : milestone, 684,

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

    section CallTarget+Inlining+NGEN
    This PR (6160) - mean (641ms)  : 628, 654
     .   : milestone, 641,
    master - mean (639ms)  : 624, 655
     .   : milestone, 639,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6160) - mean (191ms)  : 186, 195
     .   : milestone, 191,
    master - mean (192ms)  : 187, 197
     .   : milestone, 192,

    section CallTarget+Inlining+NGEN
    This PR (6160) - mean (1,100ms)  : 1071, 1129
     .   : milestone, 1100,
    master - mean (1,101ms)  : 1075, 1126
     .   : milestone, 1101,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6160) - mean (276ms)  : 273, 279
     .   : milestone, 276,
    master - mean (276ms)  : 271, 281
     .   : milestone, 276,

    section CallTarget+Inlining+NGEN
    This PR (6160) - mean (876ms)  : 849, 903
     .   : milestone, 876,
    master - mean (881ms)  : 851, 911
     .   : milestone, 881,

Loading
gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6160) - mean (266ms)  : 262, 270
     .   : milestone, 266,
    master - mean (266ms)  : 262, 269
     .   : milestone, 266,

    section CallTarget+Inlining+NGEN
    This PR (6160) - mean (856ms)  : 825, 888
     .   : milestone, 856,
    master - mean (857ms)  : 827, 886
     .   : milestone, 857,

Loading

@datadog-ddstaging
Copy link

datadog-ddstaging bot commented Oct 16, 2024

Datadog Report

Branch report: chrisnas/xunit_output_to_file
Commit report: 5fc5178
Test service: dd-trace-dotnet

✅ 0 Failed, 449755 Passed, 3198 Skipped, 21h 23m 10.89s Total Time

@andrewlock
Copy link
Member

andrewlock commented Oct 16, 2024

Benchmarks Report for tracer 🐌

Benchmarks for #6160 compared to master:

  • 2 benchmarks are slower, with geometric mean 1.199
  • 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.01μs 45.5ns 334ns 0.0158 0.00792 0 5.61 KB
master StartStopWithChild netcoreapp3.1 9.7μs 46.5ns 246ns 0.0194 0.00485 0 5.8 KB
master StartStopWithChild net472 16.2μs 55.5ns 215ns 1.03 0.292 0.0891 6.21 KB
#6160 StartStopWithChild net6.0 8.12μs 43.9ns 260ns 0.0159 0.00793 0 5.61 KB
#6160 StartStopWithChild netcoreapp3.1 10.1μs 55.7ns 339ns 0.0194 0.0097 0 5.8 KB
#6160 StartStopWithChild net472 16.1μs 62.5ns 242ns 1.05 0.311 0.09 6.2 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 250ns 934ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 654μs 257ns 926ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 864μs 283ns 1.06μs 0.431 0 0 3.3 KB
#6160 WriteAndFlushEnrichedTraces net6.0 500μs 264ns 1.02μs 0 0 0 2.7 KB
#6160 WriteAndFlushEnrichedTraces netcoreapp3.1 661μs 356ns 1.38μs 0 0 0 2.7 KB
#6160 WriteAndFlushEnrichedTraces net472 847μs 466ns 1.74μ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 151μs 879ns 7.81μs 0.146 0 0 14.47 KB
master SendRequest netcoreapp3.1 173μs 1.01μs 10μs 0.155 0 0 17.27 KB
master SendRequest net472 0.000363ns 0.000352ns 0.00132ns 0 0 0 0 b
#6160 SendRequest net6.0 147μs 838ns 6.1μs 0.152 0 0 14.47 KB
#6160 SendRequest netcoreapp3.1 167μs 946ns 7.51μs 0.179 0 0 17.27 KB
#6160 SendRequest net472 0.00238ns 0.000951ns 0.00368ns 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 556μs 2.12μs 8.2μs 0.571 0 0 41.66 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 676μs 3.09μs 14.8μs 0.37 0 0 41.73 KB
master WriteAndFlushEnrichedTraces net472 892μs 2.61μs 10.1μs 8.04 2.23 0.446 53.32 KB
#6160 WriteAndFlushEnrichedTraces net6.0 555μs 1.89μs 7.09μs 0.553 0 0 41.59 KB
#6160 WriteAndFlushEnrichedTraces netcoreapp3.1 689μs 3.23μs 14.5μs 0.349 0 0 41.79 KB
#6160 WriteAndFlushEnrichedTraces net472 856μs 2.62μs 9.81μs 8.19 2.59 0.431 53.29 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.37μs 1.21ns 4.7ns 0.0144 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.82μs 1.62ns 6.28ns 0.0137 0 0 1.02 KB
master ExecuteNonQuery net472 2.13μs 2.15ns 8.32ns 0.156 0.00108 0 987 B
#6160 ExecuteNonQuery net6.0 1.29μs 1.15ns 4.44ns 0.0143 0 0 1.02 KB
#6160 ExecuteNonQuery netcoreapp3.1 1.75μs 1.07ns 3.87ns 0.0132 0 0 1.02 KB
#6160 ExecuteNonQuery net472 2.09μs 1.45ns 5.41ns 0.156 0.00104 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.17μs 0.499ns 1.87ns 0.0136 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.58μs 0.727ns 2.72ns 0.0127 0 0 976 B
master CallElasticsearch net472 2.58μs 1.82ns 7.07ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.19μs 0.567ns 2.12ns 0.013 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.6μs 0.717ns 2.78ns 0.0137 0 0 1.02 KB
master CallElasticsearchAsync net472 2.69μs 1.03ns 3.85ns 0.166 0 0 1.05 KB
#6160 CallElasticsearch net6.0 1.12μs 0.461ns 1.73ns 0.0135 0 0 976 B
#6160 CallElasticsearch netcoreapp3.1 1.47μs 0.753ns 2.92ns 0.0132 0 0 976 B
#6160 CallElasticsearch net472 2.58μs 2.08ns 8.05ns 0.157 0 0 995 B
#6160 CallElasticsearchAsync net6.0 1.21μs 0.525ns 1.96ns 0.0135 0 0 952 B
#6160 CallElasticsearchAsync netcoreapp3.1 1.7μs 0.493ns 1.84ns 0.0136 0 0 1.02 KB
#6160 CallElasticsearchAsync net472 2.69μs 1.36ns 5.26ns 0.167 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.41μs 0.86ns 3.33ns 0.0135 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.61μs 0.577ns 2.08ns 0.0131 0 0 952 B
master ExecuteAsync net472 1.82μs 0.762ns 2.85ns 0.145 0 0 915 B
#6160 ExecuteAsync net6.0 1.36μs 0.807ns 3.02ns 0.0129 0 0 952 B
#6160 ExecuteAsync netcoreapp3.1 1.57μs 2.75ns 10.3ns 0.0132 0 0 952 B
#6160 ExecuteAsync net472 1.85μs 0.466ns 1.74ns 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.28μs 1.2ns 4.47ns 0.0323 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.42μs 15.4ns 59.8ns 0.0376 0 0 2.85 KB
master SendAsync net472 7.34μs 2.32ns 9ns 0.492 0 0 3.12 KB
#6160 SendAsync net6.0 4.38μs 1.84ns 6.88ns 0.0328 0 0 2.31 KB
#6160 SendAsync netcoreapp3.1 5.32μs 2.63ns 10.2ns 0.0371 0 0 2.85 KB
#6160 SendAsync net472 7.36μs 2.21ns 8.56ns 0.494 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.45μs 0.784ns 2.83ns 0.0226 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.18μs 0.945ns 3.54ns 0.0218 0 0 1.64 KB
master EnrichedLog net472 2.54μs 1.75ns 6.54ns 0.249 0 0 1.57 KB
#6160 EnrichedLog net6.0 1.59μs 0.807ns 3.12ns 0.023 0 0 1.64 KB
#6160 EnrichedLog netcoreapp3.1 2.27μs 0.862ns 2.99ns 0.0226 0 0 1.64 KB
#6160 EnrichedLog net472 2.63μs 1.07ns 4.02ns 0.25 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 121μs 127ns 492ns 0.0609 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 125μs 212ns 820ns 0 0 0 4.28 KB
master EnrichedLog net472 152μs 141ns 545ns 0.684 0.228 0 4.46 KB
#6160 EnrichedLog net6.0 121μs 71.2ns 266ns 0.0613 0 0 4.28 KB
#6160 EnrichedLog netcoreapp3.1 124μs 353ns 1.37μs 0 0 0 4.28 KB
#6160 EnrichedLog net472 151μs 169ns 654ns 0.676 0.225 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.2μs 1ns 3.87ns 0.0304 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.18μs 1.04ns 3.91ns 0.0293 0 0 2.2 KB
master EnrichedLog net472 4.79μs 1.61ns 5.57ns 0.318 0 0 2.02 KB
#6160 EnrichedLog net6.0 3.01μs 0.859ns 3.21ns 0.0318 0 0 2.2 KB
#6160 EnrichedLog netcoreapp3.1 4.19μs 2.54ns 9.14ns 0.0293 0 0 2.2 KB
#6160 EnrichedLog net472 4.87μs 1.29ns 4.65ns 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.33μs 0.772ns 2.99ns 0.0158 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.86μs 0.538ns 2.08ns 0.0148 0 0 1.14 KB
master SendReceive net472 2.06μs 1.59ns 5.95ns 0.183 0 0 1.16 KB
#6160 SendReceive net6.0 1.32μs 0.576ns 2.23ns 0.0159 0 0 1.14 KB
#6160 SendReceive netcoreapp3.1 1.81μs 0.556ns 2.15ns 0.015 0 0 1.14 KB
#6160 SendReceive net472 2.03μs 1.87ns 7.23ns 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.73μs 0.649ns 2.43ns 0.0218 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.99μs 2.16ns 8.38ns 0.022 0 0 1.65 KB
master EnrichedLog net472 4.29μs 2.27ns 8.48ns 0.322 0 0 2.04 KB
#6160 EnrichedLog net6.0 2.74μs 0.972ns 3.76ns 0.022 0 0 1.6 KB
#6160 EnrichedLog netcoreapp3.1 3.79μs 1.32ns 5.11ns 0.0208 0 0 1.65 KB
#6160 EnrichedLog net472 4.29μs 1.91ns 7.38ns 0.322 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #6160

Benchmark diff/base Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net472 1.240 599.32 743.01
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 1.159 481.37 557.86

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 398ns 0.624ns 2.42ns 0.008 0 0 576 B
master StartFinishSpan netcoreapp3.1 612ns 0.604ns 2.26ns 0.00772 0 0 576 B
master StartFinishSpan net472 599ns 0.633ns 2.37ns 0.0917 0 0 578 B
master StartFinishScope net6.0 482ns 0.756ns 2.93ns 0.00971 0 0 696 B
master StartFinishScope netcoreapp3.1 759ns 0.973ns 3.77ns 0.00945 0 0 696 B
master StartFinishScope net472 919ns 1.84ns 7.11ns 0.104 0 0 658 B
#6160 StartFinishSpan net6.0 395ns 0.761ns 2.95ns 0.00803 0 0 576 B
#6160 StartFinishSpan netcoreapp3.1 588ns 0.944ns 3.66ns 0.0078 0 0 576 B
#6160 StartFinishSpan net472 743ns 1.34ns 5.18ns 0.0917 0 0 578 B
#6160 StartFinishScope net6.0 558ns 0.692ns 2.68ns 0.00985 0 0 696 B
#6160 StartFinishScope netcoreapp3.1 754ns 1.32ns 5.12ns 0.00966 0 0 696 B
#6160 StartFinishScope net472 918ns 1.81ns 7.03ns 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 599ns 0.34ns 1.32ns 0.00976 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 930ns 1.45ns 5.23ns 0.00935 0 0 696 B
master RunOnMethodBegin net472 1.13μs 2.19ns 8.49ns 0.104 0 0 658 B
#6160 RunOnMethodBegin net6.0 630ns 0.861ns 3.33ns 0.00971 0 0 696 B
#6160 RunOnMethodBegin netcoreapp3.1 962ns 2.13ns 8.27ns 0.00955 0 0 696 B
#6160 RunOnMethodBegin net472 1.12μs 1.31ns 4.89ns 0.104 0 0 658 B

@andrewlock
Copy link
Member

andrewlock commented Oct 16, 2024

Throughput/Crank Report ⚡

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 (6160) (11.235M)   : 0, 11235418
    master (11.120M)   : 0, 11120201
    benchmarks/2.9.0 (11.033M)   : 0, 11032866

    section Automatic
    This PR (6160) (7.191M)   : 0, 7191074
    master (7.143M)   : 0, 7143247
    benchmarks/2.9.0 (7.786M)   : 0, 7785853

    section Trace stats
    master (7.563M)   : 0, 7562834

    section Manual
    master (11.052M)   : 0, 11051540

    section Manual + Automatic
    This PR (6160) (6.649M)   : 0, 6649215
    master (6.532M)   : 0, 6532471

    section DD_TRACE_ENABLED=0
    master (10.176M)   : 0, 10176174

Loading
gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6160) (9.522M)   : 0, 9522441
    master (9.435M)   : 0, 9435139
    benchmarks/2.9.0 (9.495M)   : 0, 9494821

    section Automatic
    This PR (6160) (6.420M)   : 0, 6419518
    master (6.301M)   : 0, 6300608

    section Trace stats
    master (6.646M)   : 0, 6646045

    section Manual
    master (9.564M)   : 0, 9563833

    section Manual + Automatic
    This PR (6160) (5.996M)   : 0, 5995764
    master (5.897M)   : 0, 5897193

    section DD_TRACE_ENABLED=0
    master (8.862M)   : 0, 8862065

Loading
gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6160) (9.718M)   : 0, 9717936
    master (9.832M)   : 0, 9832351
    benchmarks/2.9.0 (10.020M)   : 0, 10019592

    section Automatic
    This PR (6160) (6.302M)   : 0, 6302290
    master (6.258M)   : 0, 6258447
    benchmarks/2.9.0 (7.255M)   : 0, 7255257

    section Trace stats
    master (6.950M)   : 0, 6950057

    section Manual
    master (9.945M)   : 0, 9945109

    section Manual + Automatic
    This PR (6160) (5.816M)   : 0, 5816254
    master (5.742M)   : 0, 5742033

    section DD_TRACE_ENABLED=0
    master (9.091M)   : 0, 9091089

Loading

@gleocadie gleocadie force-pushed the chrisnas/xunit_output_to_file branch from 4604300 to 714e946 Compare October 28, 2024 08:12
@chrisnas chrisnas merged commit 3a46202 into master Nov 25, 2024
83 of 85 checks passed
@chrisnas chrisnas deleted the chrisnas/xunit_output_to_file branch November 25, 2024 08:47
@github-actions github-actions bot added this to the vNext-v3 milestone Nov 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area:profiler Issues related to the continous-profiler
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants