dd-trace-dotnet icon indicating copy to clipboard operation
dd-trace-dotnet copied to clipboard
verified publisher icon DataDog

[Profiler] HTTP requests profiling

Open chrisnas opened this issue 1 year ago • 2 comments

Summary of changes

Profile outgoing HTTP requests

Reason for change

New feature to pin point errors and long outgoing HTTP requests

Implementation details

Use BCL network classes events

Test coverage

Other details

chrisnas avatar Oct 11 '24 16:10 chrisnas

Datadog Report

Branch report: chrisnas/http_events Commit report: ff93c82 Test service: dd-trace-dotnet

:x: 591 Failed (7 Known Flaky), 455822 Passed, 2866 Skipped, 19h 48m 22.09s Total Time

:x: Failed Tests (591)

This report shows up to 5 failed tests.

  • ShouldAllocationProfilerBeDisabledByDefault - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error 
    
ctual:   Falsemples.Computer01.exe" should be 0 instead of -1073740940 (= 0xC0000374)

  • ShouldGetAllocationSamples - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error 
    
ctual:   Falsemples.Computer01.exe" should be 0 instead of -1073740940 (= 0xC0000374)

  • ShouldGetAllocationSamplesViaEtw - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error 
    
ctual:   Falsemples.Computer01.exe" should be 0 instead of -1073740940 (= 0xC0000374)

  • ShouldGetAllocationSamplesViaEtw - Datadog.Profiler.IntegrationTests.Allocations.AllocationsProfilerTest - Details

    Expand for error 
    
ctual:   Falsemples.Computer01.exe" should be 0 instead of -1073740940 (= 0xC0000374)

  • CheckMetadataAreSent - Datadog.Profiler.IntegrationTests.ApplicationInfo.ApplicationInfoTest - Details

    Expand for error 
    
ctual:   Falsemples.Computer01.exe" should be 0 instead of -1073740940 (= 0xC0000374)

datadog-ddstaging[bot] avatar Oct 11 '24 16:10 datadog-ddstaging[bot]

Execution-Time Benchmarks Report :stopwatch:

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 (6149) - mean (72ms)  : 64, 80
     .   : milestone, 72,
    master - mean (69ms)  : 67, 71
     .   : milestone, 69,

    section CallTarget+Inlining+NGEN
    This PR (6149) - mean (1,108ms)  : 1093, 1122
     .   : milestone, 1108,
    master - mean (1,107ms)  : 1086, 1127
     .   : milestone, 1107,


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

    section CallTarget+Inlining+NGEN
    This PR (6149) - mean (768ms)  : 755, 781
     .   : milestone, 768,
    master - mean (778ms)  : 764, 792
     .   : milestone, 778,


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

    section CallTarget+Inlining+NGEN
    This PR (6149) - mean (718ms)  : 705, 731
     .   : milestone, 718,
    master - mean (730ms)  : 715, 745
     .   : milestone, 730,


gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6149) - mean (191ms)  : 187, 196
     .   : milestone, 191,

    section CallTarget+Inlining+NGEN
    This PR (6149) - mean (1,227ms)  : 1206, 1248
     .   : milestone, 1227,


gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6149) - mean (277ms)  : 272, 282
     .   : milestone, 277,

    section CallTarget+Inlining+NGEN
    This PR (6149) - mean (947ms)  : 924, 970
     .   : milestone, 947,


gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6149) - mean (275ms)  : 254, 296
     .   : milestone, 275,

    section CallTarget+Inlining+NGEN
    This PR (6149) - mean (923ms)  : 901, 945
     .   : milestone, 923,

andrewlock avatar Oct 11 '24 16:10 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #6149 compared to master:

  • 1 benchmarks are faster, with geometric mean 1.144
  • 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 :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartStopWithChild net6.0 8.13μs 40.7ns 223ns 0.0203 0.00813 0 5.6 KB
master StartStopWithChild netcoreapp3.1 10.2μs 55.1ns 307ns 0.0245 0.0098 0 5.8 KB
master StartStopWithChild net472 16.6μs 48.7ns 189ns 1.06 0.325 0.108 6.21 KB
#6149 StartStopWithChild net6.0 8.14μs 45.3ns 283ns 0.0123 0.0041 0 5.61 KB
#6149 StartStopWithChild netcoreapp3.1 10μs 55.6ns 334ns 0.0151 0.00503 0 5.8 KB
#6149 StartStopWithChild net472 16.5μs 42.5ns 159ns 1.04 0.318 0.106 6.2 KB
Benchmarks.Trace.AgentWriterBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 467μs 326ns 1.22μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 644μs 322ns 1.25μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 833μs 425ns 1.64μs 0.417 0 0 3.3 KB
#6149 WriteAndFlushEnrichedTraces net6.0 499μs 470ns 1.82μs 0 0 0 2.7 KB
#6149 WriteAndFlushEnrichedTraces netcoreapp3.1 633μs 481ns 1.86μs 0 0 0 2.7 KB
#6149 WriteAndFlushEnrichedTraces net472 835μs 534ns 2.07μs 0.417 0 0 3.3 KB
Benchmarks.Trace.AspNetCoreBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendRequest net6.0 203μs 1.17μs 9.7μs 0.192 0 0 18.73 KB
master SendRequest netcoreapp3.1 219μs 1.25μs 8.63μs 0.21 0 0 20.89 KB
master SendRequest net472 0.00233ns 0.000599ns 0.00232ns 0 0 0 0 b
#6149 SendRequest net6.0 204μs 1.18μs 10.9μs 0.194 0 0 18.73 KB
#6149 SendRequest netcoreapp3.1 218μs 1.08μs 6.01μs 0.211 0 0 20.89 KB
#6149 SendRequest net472 9.48E‑05ns 9.48E‑05ns 0.000355ns 0 0 0 0 b
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master WriteAndFlushEnrichedTraces net6.0 569μs 2.32μs 9.86μs 0.558 0 0 41.65 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 679μs 3.42μs 15.3μs 0.334 0 0 41.74 KB
master WriteAndFlushEnrichedTraces net472 866μs 2.61μs 9.78μs 8.19 2.59 0.431 53.32 KB
#6149 WriteAndFlushEnrichedTraces net6.0 575μs 2.23μs 9.46μs 0.581 0 0 41.57 KB
#6149 WriteAndFlushEnrichedTraces netcoreapp3.1 683μs 2.38μs 9.22μs 0.336 0 0 41.81 KB
#6149 WriteAndFlushEnrichedTraces net472 858μs 3.48μs 13.5μs 8.56 2.57 0.428 53.29 KB
Benchmarks.Trace.DbCommandBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteNonQuery net6.0 1.23μs 0.792ns 3.07ns 0.0142 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.81μs 1.07ns 3.99ns 0.0135 0 0 1.02 KB
master ExecuteNonQuery net472 2.04μs 2.13ns 8.26ns 0.156 0.00102 0 987 B
#6149 ExecuteNonQuery net6.0 1.28μs 0.936ns 3.63ns 0.0141 0 0 1.02 KB
#6149 ExecuteNonQuery netcoreapp3.1 1.82μs 2.98ns 11.5ns 0.0136 0 0 1.02 KB
#6149 ExecuteNonQuery net472 2.02μs 1.63ns 6.09ns 0.157 0.00101 0 987 B
Benchmarks.Trace.ElasticsearchBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master CallElasticsearch net6.0 1.22μs 0.904ns 3.38ns 0.0134 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.6μs 1.49ns 5.77ns 0.0129 0 0 976 B
master CallElasticsearch net472 2.59μs 4.1ns 14.8ns 0.158 0 0 995 B
master CallElasticsearchAsync net6.0 1.26μs 0.926ns 3.59ns 0.0133 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.63μs 0.761ns 2.74ns 0.0139 0 0 1.02 KB
master CallElasticsearchAsync net472 2.53μs 2.2ns 8.52ns 0.166 0 0 1.05 KB
#6149 CallElasticsearch net6.0 1.24μs 0.744ns 2.79ns 0.0137 0 0 976 B
#6149 CallElasticsearch netcoreapp3.1 1.62μs 3.62ns 14ns 0.0136 0 0 976 B
#6149 CallElasticsearch net472 2.57μs 2.78ns 10.8ns 0.158 0 0 995 B
#6149 CallElasticsearchAsync net6.0 1.26μs 1.04ns 3.9ns 0.0135 0 0 952 B
#6149 CallElasticsearchAsync netcoreapp3.1 1.65μs 0.791ns 3.06ns 0.0133 0 0 1.02 KB
#6149 CallElasticsearchAsync net472 2.71μs 2.52ns 9.42ns 0.166 0 0 1.05 KB
Benchmarks.Trace.GraphQLBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master ExecuteAsync net6.0 1.38μs 0.608ns 2.28ns 0.0132 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.72μs 1.28ns 4.8ns 0.0129 0 0 952 B
master ExecuteAsync net472 1.76μs 0.524ns 1.89ns 0.145 0 0 915 B
#6149 ExecuteAsync net6.0 1.42μs 21.5ns 215ns 0.0132 0 0 952 B
#6149 ExecuteAsync netcoreapp3.1 1.77μs 0.605ns 2.18ns 0.0123 0 0 952 B
#6149 ExecuteAsync net472 1.73μs 0.809ns 3.03ns 0.145 0 0 915 B
Benchmarks.Trace.HttpClientBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendAsync net6.0 4.32μs 2.29ns 8.55ns 0.0325 0 0 2.31 KB
master SendAsync netcoreapp3.1 5.25μs 3.66ns 14.2ns 0.0395 0 0 2.85 KB
master SendAsync net472 7.55μs 1.68ns 6.51ns 0.495 0 0 3.12 KB
#6149 SendAsync net6.0 4.44μs 2.09ns 7.81ns 0.0331 0 0 2.31 KB
#6149 SendAsync netcoreapp3.1 5.26μs 3.71ns 14.4ns 0.0367 0 0 2.85 KB
#6149 SendAsync net472 7.57μs 1.58ns 6.12ns 0.495 0 0 3.12 KB
Benchmarks.Trace.ILoggerBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 1.53μs 0.98ns 3.79ns 0.023 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.26μs 0.962ns 3.47ns 0.0224 0 0 1.64 KB
master EnrichedLog net472 2.57μs 1.52ns 5.9ns 0.249 0 0 1.57 KB
#6149 EnrichedLog net6.0 1.51μs 1.03ns 3.73ns 0.0228 0 0 1.64 KB
#6149 EnrichedLog netcoreapp3.1 2.24μs 1.03ns 3.87ns 0.0223 0 0 1.64 KB
#6149 EnrichedLog net472 2.61μs 1.37ns 5.12ns 0.249 0 0 1.57 KB
Benchmarks.Trace.Log4netBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 119μs 231ns 895ns 0.0594 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 124μs 195ns 756ns 0 0 0 4.28 KB
master EnrichedLog net472 155μs 164ns 634ns 0.697 0.232 0 4.46 KB
#6149 EnrichedLog net6.0 121μs 99.2ns 384ns 0.0607 0 0 4.28 KB
#6149 EnrichedLog netcoreapp3.1 124μs 131ns 491ns 0.0626 0 0 4.28 KB
#6149 EnrichedLog net472 153μs 195ns 755ns 0.691 0.23 0 4.46 KB
Benchmarks.Trace.NLogBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.87μs 0.836ns 3.24ns 0.0301 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.19μs 1.71ns 6.62ns 0.0291 0 0 2.2 KB
master EnrichedLog net472 4.94μs 1.55ns 5.82ns 0.319 0 0 2.02 KB
#6149 EnrichedLog net6.0 3.12μs 1.36ns 5.27ns 0.0297 0 0 2.2 KB
#6149 EnrichedLog netcoreapp3.1 4.17μs 2.19ns 8.47ns 0.029 0 0 2.2 KB
#6149 EnrichedLog net472 4.93μs 1.59ns 6.16ns 0.319 0 0 2.02 KB
Benchmarks.Trace.RedisBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master SendReceive net6.0 1.35μs 1.79ns 6.93ns 0.016 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.77μs 0.842ns 3.26ns 0.0151 0 0 1.14 KB
master SendReceive net472 2.1μs 1.2ns 4.64ns 0.183 0 0 1.16 KB
#6149 SendReceive net6.0 1.3μs 0.564ns 2.11ns 0.0165 0 0 1.14 KB
#6149 SendReceive netcoreapp3.1 1.83μs 0.851ns 3.3ns 0.0154 0 0 1.14 KB
#6149 SendReceive net472 2.21μs 1.48ns 5.74ns 0.183 0 0 1.16 KB
Benchmarks.Trace.SerilogBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master EnrichedLog net6.0 2.86μs 1.68ns 6.52ns 0.0227 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.88μs 3.73ns 14.4ns 0.0217 0 0 1.65 KB
master EnrichedLog net472 4.32μs 3.06ns 11.9ns 0.323 0 0 2.04 KB
#6149 EnrichedLog net6.0 2.84μs 0.914ns 3.54ns 0.0228 0 0 1.6 KB
#6149 EnrichedLog netcoreapp3.1 3.93μs 1.54ns 5.96ns 0.0215 0 0 1.65 KB
#6149 EnrichedLog net472 4.36μs 3.73ns 14.5ns 0.324 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6149

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑net6.0 1.144 462.65 404.25

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 462ns 0.48ns 1.8ns 0.00814 0 0 576 B
master StartFinishSpan netcoreapp3.1 606ns 1.29ns 5ns 0.00788 0 0 576 B
master StartFinishSpan net472 720ns 1.02ns 3.94ns 0.0917 0 0 578 B
master StartFinishScope net6.0 533ns 0.405ns 1.57ns 0.00967 0 0 696 B
master StartFinishScope netcoreapp3.1 692ns 0.935ns 3.62ns 0.00938 0 0 696 B
master StartFinishScope net472 884ns 0.808ns 3.13ns 0.104 0 0 658 B
#6149 StartFinishSpan net6.0 405ns 0.295ns 1.14ns 0.00807 0 0 576 B
#6149 StartFinishSpan netcoreapp3.1 575ns 3.16ns 19.8ns 0.00771 0 0 576 B
#6149 StartFinishSpan net472 723ns 0.541ns 2.09ns 0.0917 0 0 578 B
#6149 StartFinishScope net6.0 567ns 0.555ns 2.15ns 0.0097 0 0 696 B
#6149 StartFinishScope netcoreapp3.1 760ns 0.498ns 1.86ns 0.00928 0 0 696 B
#6149 StartFinishScope net472 904ns 1.21ns 4.68ns 0.104 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed :heavy_check_mark: Same allocations :heavy_check_mark:

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 603ns 1.73ns 6.48ns 0.00961 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 900ns 0.624ns 2.16ns 0.0093 0 0 696 B
master RunOnMethodBegin net472 1.1μs 1.45ns 5.62ns 0.104 0 0 658 B
#6149 RunOnMethodBegin net6.0 587ns 0.546ns 2.11ns 0.00961 0 0 696 B
#6149 RunOnMethodBegin netcoreapp3.1 926ns 0.858ns 3.32ns 0.00923 0 0 696 B
#6149 RunOnMethodBegin net472 1.12μs 1.08ns 3.74ns 0.104 0 0 658 B

andrewlock avatar Nov 06 '24 13:11 andrewlock

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 (6149) (11.275M)   : 0, 11274774
    master (11.138M)   : 0, 11137526
    benchmarks/2.9.0 (11.033M)   : 0, 11032866

    section Automatic
    This PR (6149) (7.046M)   : 0, 7046440
    master (7.296M)   : 0, 7295708
    benchmarks/2.9.0 (7.786M)   : 0, 7785853

    section Trace stats
    master (7.579M)   : 0, 7579141

    section Manual
    master (11.154M)   : 0, 11154232

    section Manual + Automatic
    This PR (6149) (6.636M)   : 0, 6635677
    master (6.616M)   : 0, 6616418

    section DD_TRACE_ENABLED=0
    master (10.155M)   : 0, 10154896


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6149) (9.600M)   : 0, 9600124
    master (9.515M)   : 0, 9515388
    benchmarks/2.9.0 (9.495M)   : 0, 9494821

    section Automatic
    This PR (6149) (6.340M)   : 0, 6339905
    master (6.416M)   : 0, 6416261

    section Trace stats
    master (6.719M)   : 0, 6718560

    section Manual
    master (9.633M)   : 0, 9633358

    section Manual + Automatic
    This PR (6149) (5.899M)   : 0, 5898741
    master (5.972M)   : 0, 5972415

    section DD_TRACE_ENABLED=0
    master (8.741M)   : 0, 8740855


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6149) (9.743M)   : 0, 9743389
    master (9.435M)   : 0, 9435349
    benchmarks/2.9.0 (10.020M)   : 0, 10019592

    section Automatic
    This PR (6149) (6.759M)   : 0, 6758542
    master (6.245M)   : 0, 6244921
    benchmarks/2.9.0 (7.255M)   : 0, 7255257

    section Trace stats
    master (6.687M)   : 0, 6686776

    section Manual
    master (9.498M)   : 0, 9497601

    section Manual + Automatic
    This PR (6149) (6.290M)   : 0, 6289863
    master (5.774M)   : 0, 5773612

    section DD_TRACE_ENABLED=0
    master (9.014M)   : 0, 9013860

andrewlock avatar Nov 06 '24 14:11 andrewlock