-
Notifications
You must be signed in to change notification settings - Fork 142
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
Fix return value on error in delegate instrumentation #6153
Conversation
Datadog ReportBranch report: ✅ 0 Failed, 363916 Passed, 2070 Skipped, 14h 55m 16.96s Total Time |
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 (6153) - mean (70ms) : 68, 72
. : milestone, 70,
master - mean (70ms) : 68, 72
. : milestone, 70,
section CallTarget+Inlining+NGEN
This PR (6153) - mean (1,111ms) : 1091, 1131
. : milestone, 1111,
master - mean (1,110ms) : 1094, 1127
. : milestone, 1110,
gantt
title Execution time (ms) FakeDbCommand (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6153) - mean (109ms) : 106, 111
. : milestone, 109,
master - mean (109ms) : 106, 111
. : milestone, 109,
section CallTarget+Inlining+NGEN
This PR (6153) - mean (768ms) : 752, 785
. : milestone, 768,
master - mean (769ms) : 755, 783
. : milestone, 769,
gantt
title Execution time (ms) FakeDbCommand (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6153) - mean (92ms) : 90, 95
. : milestone, 92,
master - mean (92ms) : 89, 95
. : milestone, 92,
section CallTarget+Inlining+NGEN
This PR (6153) - mean (724ms) : 709, 740
. : milestone, 724,
master - mean (744ms) : 657, 831
. : milestone, 744,
gantt
title Execution time (ms) HttpMessageHandler (.NET Framework 4.6.2)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6153) - mean (190ms) : 186, 194
. : milestone, 190,
master - mean (189ms) : 187, 191
. : milestone, 189,
section CallTarget+Inlining+NGEN
This PR (6153) - mean (1,195ms) : 1170, 1220
. : milestone, 1195,
master - mean (1,200ms) : 1174, 1225
. : milestone, 1200,
gantt
title Execution time (ms) HttpMessageHandler (.NET Core 3.1)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6153) - mean (275ms) : 270, 280
. : milestone, 275,
master - mean (276ms) : 272, 281
. : milestone, 276,
section CallTarget+Inlining+NGEN
This PR (6153) - mean (938ms) : 922, 954
. : milestone, 938,
master - mean (939ms) : 920, 957
. : milestone, 939,
gantt
title Execution time (ms) HttpMessageHandler (.NET 6)
dateFormat X
axisFormat %s
todayMarker off
section Baseline
This PR (6153) - mean (263ms) : 259, 267
. : milestone, 263,
master - mean (266ms) : 258, 273
. : milestone, 266,
section CallTarget+Inlining+NGEN
This PR (6153) - mean (920ms) : 898, 941
. : milestone, 920,
master - mean (927ms) : 908, 946
. : milestone, 927,
|
Benchmarks Report for tracer 🐌Benchmarks for #6153 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 - Slower
|
Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
---|---|---|---|---|
Benchmarks.Trace.SpanBenchmark.StartFinishScope‑net6.0 | 1.138 | 480.77 | 546.89 | |
Benchmarks.Trace.SpanBenchmark.StartFinishSpan‑netcoreapp3.1 | 1.127 | 552.20 | 622.46 |
Raw results
Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
---|---|---|---|---|---|---|---|---|---|
master | StartFinishSpan |
net6.0 | 394ns | 0.178ns | 0.667ns | 0.00815 | 0 | 0 | 576 B |
master | StartFinishSpan |
netcoreapp3.1 | 552ns | 0.411ns | 1.48ns | 0.00778 | 0 | 0 | 576 B |
master | StartFinishSpan |
net472 | 774ns | 0.569ns | 2.2ns | 0.0915 | 0 | 0 | 578 B |
master | StartFinishScope |
net6.0 | 481ns | 0.221ns | 0.825ns | 0.00986 | 0 | 0 | 696 B |
master | StartFinishScope |
netcoreapp3.1 | 733ns | 1.4ns | 5.43ns | 0.00935 | 0 | 0 | 696 B |
master | StartFinishScope |
net472 | 947ns | 0.751ns | 2.91ns | 0.104 | 0 | 0 | 658 B |
#6153 | StartFinishSpan |
net6.0 | 408ns | 0.188ns | 0.726ns | 0.00819 | 0 | 0 | 576 B |
#6153 | StartFinishSpan |
netcoreapp3.1 | 622ns | 0.258ns | 0.967ns | 0.00759 | 0 | 0 | 576 B |
#6153 | StartFinishSpan |
net472 | 754ns | 0.511ns | 1.98ns | 0.0916 | 0 | 0 | 578 B |
#6153 | StartFinishScope |
net6.0 | 547ns | 0.228ns | 0.881ns | 0.00985 | 0 | 0 | 696 B |
#6153 | StartFinishScope |
netcoreapp3.1 | 797ns | 0.53ns | 2.05ns | 0.0092 | 0 | 0 | 696 B |
#6153 | StartFinishScope |
net472 | 882ns | 0.736ns | 2.85ns | 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 | 662ns | 0.373ns | 1.44ns | 0.00994 | 0 | 0 | 696 B |
master | RunOnMethodBegin |
netcoreapp3.1 | 927ns | 0.475ns | 1.84ns | 0.00924 | 0 | 0 | 696 B |
master | RunOnMethodBegin |
net472 | 1.13μs | 0.284ns | 0.984ns | 0.104 | 0 | 0 | 658 B |
#6153 | RunOnMethodBegin |
net6.0 | 624ns | 0.522ns | 1.95ns | 0.00985 | 0 | 0 | 696 B |
#6153 | RunOnMethodBegin |
netcoreapp3.1 | 931ns | 0.425ns | 1.65ns | 0.00958 | 0 | 0 | 696 B |
#6153 | RunOnMethodBegin |
net472 | 1.14μs | 0.721ns | 2.79ns | 0.104 | 0 | 0 | 658 B |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Oh great catch, I missed that one. Thanks for the fix
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 (6153) (11.146M) : 0, 11145781
master (11.137M) : 0, 11137140
benchmarks/2.9.0 (11.081M) : 0, 11080577
section Automatic
This PR (6153) (7.302M) : 0, 7301913
master (7.371M) : 0, 7370758
benchmarks/2.9.0 (7.732M) : 0, 7732233
section Trace stats
master (7.797M) : 0, 7797307
section Manual
master (11.111M) : 0, 11110541
section Manual + Automatic
This PR (6153) (6.664M) : 0, 6664314
master (6.715M) : 0, 6715013
section DD_TRACE_ENABLED=0
master (10.145M) : 0, 10144731
gantt
title Throughput Linux arm64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6153) (9.637M) : 0, 9637424
master (9.288M) : 0, 9287840
benchmarks/2.9.0 (9.798M) : 0, 9798067
section Automatic
This PR (6153) (6.525M) : 0, 6525047
master (6.397M) : 0, 6396905
section Trace stats
master (6.866M) : 0, 6865601
section Manual
master (9.556M) : 0, 9555874
section Manual + Automatic
This PR (6153) (6.005M) : 0, 6004519
master (6.065M) : 0, 6065089
section DD_TRACE_ENABLED=0
master (8.502M) : 0, 8501634
gantt
title Throughput Windows x64 (Total requests)
dateFormat X
axisFormat %s
section Baseline
This PR (6153) (10.253M) : 0, 10253347
master (10.368M) : 0, 10368181
benchmarks/2.9.0 (10.067M) : 0, 10067315
section Automatic
This PR (6153) (6.941M) : 0, 6941022
master (6.778M) : 0, 6777658
benchmarks/2.9.0 (7.552M) : 0, 7552193
section Trace stats
master (7.515M) : 0, 7514665
section Manual
master (10.210M) : 0, 10210161
section Manual + Automatic
This PR (6153) (6.524M) : 0, 6523525
master (6.466M) : 0, 6466038
section DD_TRACE_ENABLED=0
master (9.590M) : 0, 9589809
|
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Nice catch 👍
Summary of changes
In the delegate instrumentation, when the async callback failed, we returned a default value instead of the original value.
Reason for change
The instrumented method probably had a good reason to return that value to begin with.
Implementation details
Just set the value in the catch block.
Test coverage
Added tests to cover the "failure in callback" case.
Also, fixed a flake in the async test (which is actually the reason why I looked at this code to begin with). The tests were relying on the order of execution of the
onDelegateEnd
/onDelegateAsyncEnd
callbacks, but their order is not guaranteed (becauseonDelegateAsyncEnd
is invoked asynchronously and not awaited).