[Profiler] Make sure we log only once for DebugInfoStore errors #6187
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
github-actions
bot
added
the
area:profiler
Datadog ReportBranch report: ✅ 0 Failed, 367939 Passed, 2397 Skipped, 16h 46m 43.55s Total Time New Flaky Tests (1)
|
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:
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,
|
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 (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
|
Benchmarks Report for tracer 🐌Benchmarks for #6187 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.ActivityBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.CIVisibilityProtocolWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.SpanBenchmark - Faster 🎉 Same allocations ✔️
|
| 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 🎉 Same allocations ✔️
Faster 🎉 in #6187
Benchmark
base/diff
Base Median (ns)
Diff Median (ns)
Modality
Benchmarks.Trace.TraceAnnotationsBenchmark.RunOnMethodBegin‑net6.0
1.219
718.11
589.15
| 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 |
chrisnas
approved these changes
Oct 24, 2024
| auto alreadyLogged = std::exchange(info.ErrorLogged, true); | ||
| if (!alreadyLogged) | ||
| { | ||
| Log::Info("The debug info for the module `", moduleId, "` seems to be invalid (is valid? '", info.IsValid, "') or the RID is out of the symbols array bounds (RID: ", |
There was a problem hiding this comment.
- it could be easier to log one or the other case so the lines will be explicit what is wrong (invalid or RID)
- provide the corresponding filename to avoid having to find it elsewhere in the log file based on the moduleID value
gleocadie
force-pushed
the
gleocadie/fix-too-much-logging-message-for-debug-info-store
branch
2 times, most recently
from
4db3041
to
7de53cf
Compare
gleocadie
force-pushed
the
gleocadie/fix-too-much-logging-message-for-debug-info-store
branch
from
6eb8297
to
28e4fde
Compare
gleocadie
deleted the
gleocadie/fix-too-much-logging-message-for-debug-info-store
branch
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
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.
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