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

[Profiler] Make sure we log only once for DebugInfoStore errors

Open gleocadie opened this issue 1 year ago • 3 comments

Summary of changes

Make sure that in case of errors, the DebugInfoStore (line number feature) logs only once the error per module.

Reason for change

When enabling the "line number" feature, if a module is invalid (does not exist, discrepancies between the pdb and the image...), we log an error each time we ask for debug info.

[2024-10-23 12:46:18.933 | info | PId: 21 | TId: 21] The debug info for the module `140011354144768` seems to be invalid (is valid? '0') or the RID is out of the symbols array bounds (RID: 23527). Number of debug info: 0

This clutters the log file and does not help.

Implementation details

Add a field per module datatstructure that says if the error was already logged for that module.

Test coverage

Other details

gleocadie avatar Oct 23 '24 15:10 gleocadie

Datadog Report

Branch report: gleocadie/fix-too-much-logging-message-for-debug-info-store Commit report: 28e4fde Test service: dd-trace-dotnet

:white_check_mark: 0 Failed, 367939 Passed, 2397 Skipped, 16h 46m 43.55s Total Time :snowflake: 1 New Flaky

New Flaky Tests (1)

  • ReturnMethods - Datadog.Trace.DuckTyping.Tests.Methods.MethodTests - Last Failure

    Expand for error 
    ad binary signature. (0x80131192)

datadog-ddstaging[bot] avatar Oct 23 '24 15: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 (6187) - mean (71ms)  : 68, 73
     .   : milestone, 71,
    master - mean (70ms)  : 67, 73
     .   : milestone, 70,

    section CallTarget+Inlining+NGEN
    This PR (6187) - mean (1,117ms)  : 1099, 1135
     .   : milestone, 1117,
    master - mean (1,115ms)  : 1092, 1137
     .   : milestone, 1115,


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

    section CallTarget+Inlining+NGEN
    This PR (6187) - mean (777ms)  : 761, 793
     .   : milestone, 777,
    master - mean (776ms)  : 758, 793
     .   : milestone, 776,


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

    section CallTarget+Inlining+NGEN
    This PR (6187) - mean (732ms)  : 709, 754
     .   : milestone, 732,
    master - mean (733ms)  : 715, 752
     .   : milestone, 733,


gantt
    title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6187) - mean (190ms)  : 187, 194
     .   : milestone, 190,
    master - mean (191ms)  : 188, 193
     .   : milestone, 191,

    section CallTarget+Inlining+NGEN
    This PR (6187) - mean (1,198ms)  : 1169, 1227
     .   : milestone, 1198,
    master - mean (1,201ms)  : 1174, 1229
     .   : milestone, 1201,


gantt
    title Execution time (ms) HttpMessageHandler (.NET Core 3.1) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6187) - mean (276ms)  : 271, 282
     .   : milestone, 276,
    master - mean (276ms)  : 271, 280
     .   : milestone, 276,

    section CallTarget+Inlining+NGEN
    This PR (6187) - mean (944ms)  : 929, 958
     .   : milestone, 944,
    master - mean (944ms)  : 929, 958
     .   : milestone, 944,


gantt
    title Execution time (ms) HttpMessageHandler (.NET 6) 
    dateFormat  X
    axisFormat %s
    todayMarker off
    section Baseline
    This PR (6187) - mean (264ms)  : 260, 268
     .   : milestone, 264,
    master - mean (265ms)  : 261, 269
     .   : milestone, 265,

    section CallTarget+Inlining+NGEN
    This PR (6187) - mean (925ms)  : 909, 941
     .   : milestone, 925,
    master - mean (930ms)  : 907, 952
     .   : milestone, 930,

andrewlock avatar Oct 23 '24 15:10 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 (6187) (11.212M)   : 0, 11212128
    master (11.105M)   : 0, 11105195
    benchmarks/2.9.0 (11.081M)   : 0, 11080577

    section Automatic
    This PR (6187) (7.431M)   : 0, 7430973
    master (7.340M)   : 0, 7340153
    benchmarks/2.9.0 (7.732M)   : 0, 7732233

    section Trace stats
    master (7.684M)   : 0, 7683674

    section Manual
    master (11.156M)   : 0, 11156416

    section Manual + Automatic
    This PR (6187) (6.780M)   : 0, 6780095
    master (6.781M)   : 0, 6780718

    section DD_TRACE_ENABLED=0
    master (10.185M)   : 0, 10184862


gantt
    title Throughput Linux arm64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6187) (9.693M)   : 0, 9693467
    master (9.706M)   : 0, 9705913
    benchmarks/2.9.0 (9.798M)   : 0, 9798067

    section Automatic
    This PR (6187) (6.674M)   : 0, 6674200
    master (6.630M)   : 0, 6629991

    section Trace stats
    master (6.875M)   : 0, 6875083

    section Manual
    master (9.889M)   : 0, 9888676

    section Manual + Automatic
    This PR (6187) (6.045M)   : 0, 6044962
    master (6.141M)   : 0, 6141000

    section DD_TRACE_ENABLED=0
    master (8.730M)   : 0, 8730095


gantt
    title Throughput Windows x64 (Total requests) 
    dateFormat  X
    axisFormat %s
    section Baseline
    This PR (6187) (9.924M)   : 0, 9924444
    master (9.754M)   : 0, 9754019
    benchmarks/2.9.0 (10.067M)   : 0, 10067315

    section Automatic
    This PR (6187) (6.384M)   : 0, 6384420
    master (6.532M)   : 0, 6531758
    benchmarks/2.9.0 (7.552M)   : 0, 7552193

    section Trace stats
    master (7.247M)   : 0, 7247385

    section Manual
    master (10.192M)   : 0, 10191876

    section Manual + Automatic
    This PR (6187) (5.921M)   : 0, 5921195
    master (6.026M)   : 0, 6025810

    section DD_TRACE_ENABLED=0
    master (8.972M)   : 0, 8972251

andrewlock avatar Oct 23 '24 16:10 andrewlock

Benchmarks Report for tracer :snail:

Benchmarks for #6187 compared to master:

  • 2 benchmarks are faster, with geometric mean 1.214
  • 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 7.82μs 43.7ns 309ns 0.0195 0.00781 0 5.43 KB
master StartStopWithChild netcoreapp3.1 9.9μs 56ns 392ns 0.0189 0.00947 0 5.61 KB
master StartStopWithChild net472 16.2μs 50.7ns 197ns 1.02 0.315 0.0888 6.06 KB
#6187 StartStopWithChild net6.0 7.77μs 44ns 302ns 0.0117 0.00389 0 5.43 KB
#6187 StartStopWithChild netcoreapp3.1 9.9μs 53.5ns 312ns 0.0145 0.00484 0 5.63 KB
#6187 StartStopWithChild net472 16.3μs 68.4ns 265ns 1.01 0.285 0.0976 6.06 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 483μs 196ns 759ns 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 638μs 365ns 1.36μs 0 0 0 2.7 KB
master WriteAndFlushEnrichedTraces net472 847μs 319ns 1.24μs 0.422 0 0 3.3 KB
#6187 WriteAndFlushEnrichedTraces net6.0 477μs 303ns 1.17μs 0 0 0 2.7 KB
#6187 WriteAndFlushEnrichedTraces netcoreapp3.1 642μs 370ns 1.43μs 0 0 0 2.7 KB
#6187 WriteAndFlushEnrichedTraces net472 836μs 545ns 2.11μ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 200μs 1.13μs 9.87μs 0.195 0 0 18.45 KB
master SendRequest netcoreapp3.1 221μs 1.29μs 11.1μs 0.213 0 0 20.61 KB
master SendRequest net472 0.0013ns 0.000741ns 0.00277ns 0 0 0 0 b
#6187 SendRequest net6.0 202μs 1.15μs 8.79μs 0.205 0 0 18.45 KB
#6187 SendRequest netcoreapp3.1 222μs 1.28μs 10.3μs 0.214 0 0 20.61 KB
#6187 SendRequest net472 0.000346ns 0.000185ns 0.000717ns 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 578μs 2.64μs 12.1μs 0.571 0 0 41.75 KB
master WriteAndFlushEnrichedTraces netcoreapp3.1 686μs 3.25μs 16.3μs 0.349 0 0 41.79 KB
master WriteAndFlushEnrichedTraces net472 858μs 4.08μs 17.3μs 8.39 2.52 0.419 53.29 KB
#6187 WriteAndFlushEnrichedTraces net6.0 574μs 2.88μs 13.2μs 0.604 0 0 41.63 KB
#6187 WriteAndFlushEnrichedTraces netcoreapp3.1 689μs 3.7μs 20.6μs 0.342 0 0 41.77 KB
#6187 WriteAndFlushEnrichedTraces net472 858μs 2.5μs 9.03μs 8.3 2.62 0.437 53.25 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.28μs 1.14ns 4.42ns 0.0141 0 0 1.02 KB
master ExecuteNonQuery netcoreapp3.1 1.78μs 1.15ns 4.44ns 0.0133 0 0 1.02 KB
master ExecuteNonQuery net472 2.14μs 3.24ns 11.7ns 0.157 0 0 987 B
#6187 ExecuteNonQuery net6.0 1.32μs 1.32ns 5.11ns 0.014 0 0 1.02 KB
#6187 ExecuteNonQuery netcoreapp3.1 1.78μs 5.72ns 22.2ns 0.014 0 0 1.02 KB
#6187 ExecuteNonQuery net472 2.16μs 7.3ns 28.3ns 0.156 0 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.417ns 1.56ns 0.0135 0 0 976 B
master CallElasticsearch netcoreapp3.1 1.54μs 0.472ns 1.76ns 0.0131 0 0 976 B
master CallElasticsearch net472 2.49μs 1.66ns 6.19ns 0.157 0 0 995 B
master CallElasticsearchAsync net6.0 1.28μs 0.802ns 2.78ns 0.0134 0 0 952 B
master CallElasticsearchAsync netcoreapp3.1 1.69μs 0.499ns 1.87ns 0.0135 0 0 1.02 KB
master CallElasticsearchAsync net472 2.56μs 4.06ns 15.2ns 0.167 0 0 1.05 KB
#6187 CallElasticsearch net6.0 1.24μs 0.621ns 2.32ns 0.0137 0 0 976 B
#6187 CallElasticsearch netcoreapp3.1 1.51μs 2.21ns 8.56ns 0.013 0 0 976 B
#6187 CallElasticsearch net472 2.54μs 1.89ns 7.33ns 0.158 0 0 995 B
#6187 CallElasticsearchAsync net6.0 1.28μs 0.53ns 1.98ns 0.0134 0 0 952 B
#6187 CallElasticsearchAsync netcoreapp3.1 1.66μs 0.715ns 2.58ns 0.014 0 0 1.02 KB
#6187 CallElasticsearchAsync net472 2.59μs 4.35ns 16.8ns 0.167 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.23μs 0.827ns 3.1ns 0.0135 0 0 952 B
master ExecuteAsync netcoreapp3.1 1.63μs 1.17ns 4.38ns 0.0132 0 0 952 B
master ExecuteAsync net472 1.79μs 1.25ns 4.84ns 0.145 0 0 915 B
#6187 ExecuteAsync net6.0 1.19μs 0.536ns 2ns 0.0131 0 0 952 B
#6187 ExecuteAsync netcoreapp3.1 1.61μs 0.633ns 2.45ns 0.013 0 0 952 B
#6187 ExecuteAsync net472 1.79μs 0.4ns 1.55ns 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.21μs 2.49ns 9.65ns 0.0298 0 0 2.22 KB
master SendAsync netcoreapp3.1 5.23μs 3.58ns 13.9ns 0.0366 0 0 2.76 KB
master SendAsync net472 7.88μs 3.69ns 14.3ns 0.498 0 0 3.15 KB
#6187 SendAsync net6.0 4.21μs 1.35ns 5.24ns 0.0314 0 0 2.22 KB
#6187 SendAsync netcoreapp3.1 5.09μs 2.91ns 10.5ns 0.036 0 0 2.76 KB
#6187 SendAsync net472 7.81μs 2.42ns 9.05ns 0.497 0 0 3.15 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.55μs 1.38ns 4.96ns 0.0235 0 0 1.64 KB
master EnrichedLog netcoreapp3.1 2.23μs 1.02ns 3.95ns 0.0223 0 0 1.64 KB
master EnrichedLog net472 2.6μs 1.31ns 4.92ns 0.249 0 0 1.57 KB
#6187 EnrichedLog net6.0 1.52μs 0.567ns 2.12ns 0.0227 0 0 1.64 KB
#6187 EnrichedLog netcoreapp3.1 2.26μs 0.953ns 3.69ns 0.0216 0 0 1.64 KB
#6187 EnrichedLog net472 2.71μs 1.47ns 5.7ns 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 116μs 240ns 931ns 0.0576 0 0 4.28 KB
master EnrichedLog netcoreapp3.1 122μs 200ns 773ns 0 0 0 4.28 KB
master EnrichedLog net472 151μs 197ns 762ns 0.682 0.227 0 4.46 KB
#6187 EnrichedLog net6.0 115μs 200ns 776ns 0.0576 0 0 4.28 KB
#6187 EnrichedLog netcoreapp3.1 122μs 134ns 519ns 0 0 0 4.28 KB
#6187 EnrichedLog net472 149μs 126ns 489ns 0.674 0.225 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 3.16μs 1.34ns 5.2ns 0.0299 0 0 2.2 KB
master EnrichedLog netcoreapp3.1 4.19μs 2.95ns 11.4ns 0.0292 0 0 2.2 KB
master EnrichedLog net472 4.8μs 3.62ns 14ns 0.319 0 0 2.02 KB
#6187 EnrichedLog net6.0 2.92μs 0.976ns 3.52ns 0.0307 0 0 2.2 KB
#6187 EnrichedLog netcoreapp3.1 4.29μs 4.01ns 15.5ns 0.0278 0 0 2.2 KB
#6187 EnrichedLog net472 4.78μs 1.79ns 6.68ns 0.32 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.34μs 0.469ns 1.82ns 0.016 0 0 1.14 KB
master SendReceive netcoreapp3.1 1.76μs 1.1ns 4.27ns 0.0149 0 0 1.14 KB
master SendReceive net472 2.16μs 1.51ns 5.83ns 0.183 0.00109 0 1.16 KB
#6187 SendReceive net6.0 1.31μs 0.639ns 2.48ns 0.016 0 0 1.14 KB
#6187 SendReceive netcoreapp3.1 1.83μs 1.3ns 5.02ns 0.0156 0 0 1.14 KB
#6187 SendReceive net472 2.13μs 0.993ns 3.85ns 0.183 0.00105 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.62μs 0.907ns 3.39ns 0.0222 0 0 1.6 KB
master EnrichedLog netcoreapp3.1 3.95μs 2.26ns 8.76ns 0.0217 0 0 1.65 KB
master EnrichedLog net472 4.25μs 2.78ns 10.8ns 0.322 0 0 2.04 KB
#6187 EnrichedLog net6.0 2.77μs 1.8ns 6.97ns 0.0221 0 0 1.6 KB
#6187 EnrichedLog netcoreapp3.1 3.84μs 1.59ns 6.17ns 0.0215 0 0 1.65 KB
#6187 EnrichedLog net472 4.37μs 1.62ns 5.61ns 0.322 0 0 2.04 KB
Benchmarks.Trace.SpanBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6187

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 1.209 678.80 561.24

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master StartFinishSpan net6.0 397ns 0.315ns 1.14ns 0.00797 0 0 576 B
master StartFinishSpan netcoreapp3.1 679ns 0.642ns 2.49ns 0.00748 0 0 576 B
master StartFinishSpan net472 703ns 0.425ns 1.53ns 0.0918 0 0 578 B
master StartFinishScope net6.0 500ns 0.363ns 1.41ns 0.00979 0 0 696 B
master StartFinishScope netcoreapp3.1 709ns 3.69ns 18.1ns 0.00947 0 0 696 B
master StartFinishScope net472 899ns 0.493ns 1.85ns 0.104 0 0 658 B
#6187 StartFinishSpan net6.0 398ns 0.248ns 0.962ns 0.00799 0 0 576 B
#6187 StartFinishSpan netcoreapp3.1 561ns 0.293ns 1.14ns 0.00759 0 0 576 B
#6187 StartFinishSpan net472 692ns 0.744ns 2.88ns 0.0916 0 0 578 B
#6187 StartFinishScope net6.0 486ns 0.328ns 1.27ns 0.0097 0 0 696 B
#6187 StartFinishScope netcoreapp3.1 731ns 0.525ns 2.03ns 0.0095 0 0 696 B
#6187 StartFinishScope net472 898ns 1.03ns 4ns 0.105 0 0 658 B
Benchmarks.Trace.TraceAnnotationsBenchmark - Faster :tada: Same allocations :heavy_check_mark:

Faster :tada: in #6187

Benchmark base/diff Base Median (ns) Diff Median (ns) Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0 1.219 718.11 589.15

Raw results

Branch Method Toolchain Mean StdError StdDev Gen 0 Gen 1 Gen 2 Allocated
master RunOnMethodBegin net6.0 718ns 0.412ns 1.6ns 0.00962 0 0 696 B
master RunOnMethodBegin netcoreapp3.1 911ns 0.504ns 1.95ns 0.00969 0 0 696 B
master RunOnMethodBegin net472 1.18μs 0.881ns 3.41ns 0.104 0 0 658 B
#6187 RunOnMethodBegin net6.0 590ns 0.509ns 1.97ns 0.00966 0 0 696 B
#6187 RunOnMethodBegin netcoreapp3.1 887ns 0.547ns 2.05ns 0.00923 0 0 696 B
#6187 RunOnMethodBegin net472 1.16μs 0.69ns 2.67ns 0.104 0 0 658 B

andrewlock avatar Oct 24 '24 00:10 andrewlock