[Debugger] Add support for probes in async methods#3079
Conversation
GreenMatan
left a comment
There was a problem hiding this comment.
I'm posting my first batch of comments, concentrated around the managed side.
I'll review the native side separately.
e47f446 to
1184cc5
Compare
1184cc5 to
f15a667
Compare
This comment has been minimized.
This comment has been minimized.
f15a667 to
effd9f9
Compare
This comment has been minimized.
This comment has been minimized.
5f08851 to
6ece0c7
Compare
zacharycmontoya
left a comment
There was a problem hiding this comment.
From the Tracer point-of-view, everything looks good to me 👍🏼
401bed9 to
fe1d802
Compare
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
e7b4f97 to
91838ba
Compare
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
This comment has been minimized.
# Conflicts: # tracer/src/Datadog.Trace.ClrProfiler.Native/debugger_rejit_preprocessor.cpp
91838ba to
44115f2
Compare
Benchmarks Report 🐌Benchmarks for #3079 compared to master:
The following thresholds were used for comparing the benchmark speeds:
Allocation changes below 0.5% are ignored. Benchmark detailsBenchmarks.Trace.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️Raw results
Benchmarks.Trace.AppSecBodyBenchmark - Slower
|
| Benchmark | diff/base | Base Median (ns) | Diff Median (ns) | Modality |
|---|---|---|---|---|
| Benchmarks.Trace.AppSecBodyBenchmark.AllCycleMoreComplexBody‑net472 | 1.267 | 182.54 | 231.24 |
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | AllCycleSimpleBody |
net472 | 185ns | 0.145ns | 0.521ns | 0.0676 | 0 | 0 | 425 B |
| master | AllCycleSimpleBody |
netcoreapp3.1 | 236ns | 0.344ns | 1.33ns | 0.00583 | 0 | 0 | 424 B |
| master | AllCycleMoreComplexBody |
net472 | 183ns | 0.0798ns | 0.288ns | 0.0638 | 0 | 0 | 401 B |
| master | AllCycleMoreComplexBody |
netcoreapp3.1 | 233ns | 0.304ns | 1.18ns | 0.00543 | 0 | 0 | 400 B |
| master | BodyExtractorSimpleBody |
net472 | 257ns | 0.269ns | 1.04ns | 0.0573 | 0 | 0 | 361 B |
| master | BodyExtractorSimpleBody |
netcoreapp3.1 | 230ns | 0.369ns | 1.43ns | 0.00372 | 0 | 0 | 272 B |
| master | BodyExtractorMoreComplexBody |
net472 | 14.2μs | 12.9ns | 50.1ns | 1.21 | 0.0214 | 0 | 7.62 KB |
| master | BodyExtractorMoreComplexBody |
netcoreapp3.1 | 12.3μs | 11.5ns | 44.4ns | 0.0927 | 0 | 0 | 6.75 KB |
| #3079 | AllCycleSimpleBody |
net472 | 186ns | 0.193ns | 0.746ns | 0.0676 | 9.2E-05 | 0 | 425 B |
| #3079 | AllCycleSimpleBody |
netcoreapp3.1 | 238ns | 0.505ns | 1.96ns | 0.00586 | 0 | 0 | 424 B |
| #3079 | AllCycleMoreComplexBody |
net472 | 231ns | 0.133ns | 0.461ns | 0.0637 | 0 | 0 | 401 B |
| #3079 | AllCycleMoreComplexBody |
netcoreapp3.1 | 234ns | 0.219ns | 0.819ns | 0.00551 | 0 | 0 | 400 B |
| #3079 | BodyExtractorSimpleBody |
net472 | 261ns | 0.27ns | 1.04ns | 0.0573 | 0 | 0 | 361 B |
| #3079 | BodyExtractorSimpleBody |
netcoreapp3.1 | 225ns | 0.307ns | 1.15ns | 0.00374 | 0 | 0 | 272 B |
| #3079 | BodyExtractorMoreComplexBody |
net472 | 14.2μs | 15.6ns | 58.5ns | 1.21 | 0.0212 | 0 | 7.62 KB |
| #3079 | BodyExtractorMoreComplexBody |
netcoreapp3.1 | 12.2μs | 13ns | 50.2ns | 0.0921 | 0 | 0 | 6.75 KB |
Benchmarks.Trace.AspNetCoreBenchmark - Unknown 🤷 Same allocations ✔️
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | SendRequest |
net472 | 0ns | 0ns | 0ns | 0 | 0 | 0 | 0 b |
| master | SendRequest |
netcoreapp3.1 | 184μs | 302ns | 1.17μs | 0.184 | 0 | 0 | 20.57 KB |
| #3079 | SendRequest |
net472 | 0ns | 0ns | 0ns | 0 | 0 | 0 | 0 b |
| #3079 | SendRequest |
netcoreapp3.1 | 186μs | 429ns | 1.66μs | 0.184 | 0 | 0 | 20.57 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 |
net472 | 1.94μs | 0.461ns | 1.73ns | 0.15 | 0.000975 | 0 | 947 B |
| master | ExecuteNonQuery |
netcoreapp3.1 | 1.44μs | 0.432ns | 1.67ns | 0.0124 | 0 | 0 | 936 B |
| #3079 | ExecuteNonQuery |
net472 | 1.91μs | 0.606ns | 2.27ns | 0.15 | 0.000952 | 0 | 947 B |
| #3079 | ExecuteNonQuery |
netcoreapp3.1 | 1.46μs | 0.593ns | 2.05ns | 0.0123 | 0 | 0 | 936 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 |
net472 | 2.38μs | 1.21ns | 4.67ns | 0.184 | 0 | 0 | 1.16 KB |
| master | CallElasticsearch |
netcoreapp3.1 | 1.6μs | 0.874ns | 3.27ns | 0.0146 | 0 | 0 | 1.1 KB |
| master | CallElasticsearchAsync |
net472 | 2.76μs | 1.4ns | 5.43ns | 0.205 | 0 | 0 | 1.29 KB |
| master | CallElasticsearchAsync |
netcoreapp3.1 | 1.58μs | 0.709ns | 2.74ns | 0.0166 | 0 | 0 | 1.22 KB |
| #3079 | CallElasticsearch |
net472 | 2.53μs | 0.656ns | 2.54ns | 0.183 | 0 | 0 | 1.16 KB |
| #3079 | CallElasticsearch |
netcoreapp3.1 | 1.6μs | 0.515ns | 2ns | 0.0151 | 0 | 0 | 1.1 KB |
| #3079 | CallElasticsearchAsync |
net472 | 2.65μs | 1.36ns | 5.07ns | 0.204 | 0 | 0 | 1.29 KB |
| #3079 | CallElasticsearchAsync |
netcoreapp3.1 | 1.58μs | 0.59ns | 2.13ns | 0.0166 | 0 | 0 | 1.22 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 |
net472 | 2.7μs | 4.34ns | 15.7ns | 0.223 | 0 | 0 | 1.41 KB |
| master | ExecuteAsync |
netcoreapp3.1 | 1.7μs | 2.66ns | 9.59ns | 0.0177 | 0 | 0 | 1.34 KB |
| #3079 | ExecuteAsync |
net472 | 2.58μs | 8.78ns | 34ns | 0.224 | 0 | 0 | 1.41 KB |
| #3079 | ExecuteAsync |
netcoreapp3.1 | 1.77μs | 2.6ns | 10.1ns | 0.0175 | 0 | 0 | 1.34 KB |
Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | SendAsync |
net472 | 5.8μs | 14.7ns | 57.1ns | 0.439 | 0 | 0 | 2.77 KB |
| master | SendAsync |
netcoreapp3.1 | 3.76μs | 8.64ns | 33.4ns | 0.0343 | 0 | 0 | 2.6 KB |
| #3079 | SendAsync |
net472 | 5.91μs | 15.3ns | 59.2ns | 0.439 | 0 | 0 | 2.77 KB |
| #3079 | SendAsync |
netcoreapp3.1 | 3.64μs | 9.07ns | 35.1ns | 0.0345 | 0 | 0 | 2.6 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 |
net472 | 3.27μs | 3.79ns | 14.7ns | 0.288 | 0 | 0 | 1.81 KB |
| master | EnrichedLog |
netcoreapp3.1 | 2.54μs | 1.68ns | 6.3ns | 0.0254 | 0 | 0 | 1.85 KB |
| #3079 | EnrichedLog |
net472 | 3.3μs | 3.49ns | 13.1ns | 0.287 | 0 | 0 | 1.81 KB |
| #3079 | EnrichedLog |
netcoreapp3.1 | 2.58μs | 0.674ns | 2.43ns | 0.0255 | 0 | 0 | 1.85 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 |
net472 | 152μs | 162ns | 629ns | 0.674 | 0.225 | 0 | 4.65 KB |
| master | EnrichedLog |
netcoreapp3.1 | 117μs | 173ns | 669ns | 0 | 0 | 0 | 4.49 KB |
| #3079 | EnrichedLog |
net472 | 149μs | 107ns | 401ns | 0.677 | 0.226 | 0 | 4.65 KB |
| #3079 | EnrichedLog |
netcoreapp3.1 | 116μs | 248ns | 962ns | 0.0577 | 0 | 0 | 4.49 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 |
net472 | 5.75μs | 15.4ns | 59.6ns | 0.569 | 0.00292 | 0 | 3.59 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4.49μs | 7.87ns | 29.4ns | 0.0541 | 0 | 0 | 3.91 KB |
| #3079 | EnrichedLog |
net472 | 5.69μs | 20.9ns | 80.8ns | 0.57 | 0.00281 | 0 | 3.59 KB |
| #3079 | EnrichedLog |
netcoreapp3.1 | 4.34μs | 8.98ns | 33.6ns | 0.0533 | 0 | 0 | 3.91 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 |
net472 | 2.37μs | 2.21ns | 8.57ns | 0.217 | 0 | 0 | 1.37 KB |
| master | SendReceive |
netcoreapp3.1 | 1.92μs | 0.935ns | 3.62ns | 0.0182 | 0 | 0 | 1.32 KB |
| #3079 | SendReceive |
net472 | 2.24μs | 3.61ns | 13.5ns | 0.218 | 0 | 0 | 1.37 KB |
| #3079 | SendReceive |
netcoreapp3.1 | 1.9μs | 0.677ns | 2.53ns | 0.0181 | 0 | 0 | 1.32 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 |
net472 | 4.89μs | 1.79ns | 6.45ns | 0.353 | 0 | 0 | 2.23 KB |
| master | EnrichedLog |
netcoreapp3.1 | 4.36μs | 2.29ns | 8.26ns | 0.024 | 0 | 0 | 1.8 KB |
| #3079 | EnrichedLog |
net472 | 5.09μs | 1.55ns | 5.99ns | 0.354 | 0 | 0 | 2.23 KB |
| #3079 | EnrichedLog |
netcoreapp3.1 | 4.27μs | 2.8ns | 10.8ns | 0.0234 | 0 | 0 | 1.8 KB |
Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️
Raw results
| Branch | Method | Toolchain | Mean | StdError | StdDev | Gen 0 | Gen 1 | Gen 2 | Allocated |
|---|---|---|---|---|---|---|---|---|---|
| master | StartFinishSpan |
net472 | 1.17μs | 1.73ns | 6.69ns | 0.129 | 0 | 0 | 810 B |
| master | StartFinishSpan |
netcoreapp3.1 | 958ns | 0.193ns | 0.695ns | 0.0105 | 0 | 0 | 760 B |
| master | StartFinishScope |
net472 | 1.4μs | 1.45ns | 5.61ns | 0.142 | 0 | 0 | 891 B |
| master | StartFinishScope |
netcoreapp3.1 | 1.12μs | 0.425ns | 1.59ns | 0.0118 | 0 | 0 | 880 B |
| #3079 | StartFinishSpan |
net472 | 1.14μs | 0.576ns | 2.23ns | 0.129 | 0 | 0 | 810 B |
| #3079 | StartFinishSpan |
netcoreapp3.1 | 922ns | 0.204ns | 0.735ns | 0.0106 | 0 | 0 | 760 B |
| #3079 | StartFinishScope |
net472 | 1.4μs | 0.663ns | 2.57ns | 0.141 | 0 | 0 | 891 B |
| #3079 | StartFinishScope |
netcoreapp3.1 | 1.12μs | 0.41ns | 1.53ns | 0.0118 | 0 | 0 | 880 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 |
net472 | 1.53μs | 0.695ns | 2.69ns | 0.141 | 0 | 0 | 891 B |
| master | RunOnMethodBegin |
netcoreapp3.1 | 1.22μs | 0.45ns | 1.68ns | 0.0121 | 0 | 0 | 880 B |
| #3079 | RunOnMethodBegin |
net472 | 1.49μs | 0.604ns | 2.34ns | 0.141 | 0 | 0 | 891 B |
| #3079 | RunOnMethodBegin |
netcoreapp3.1 | 1.19μs | 0.544ns | 2.04ns | 0.012 | 0 | 0 | 880 B |
Code Coverage Report 📊
View the full report for further details: Datadog.Trace Breakdown
|
| master | #3079 | Change | |
|---|---|---|---|
| Lines % | 73% |
73% |
-1% |
| Branches % | 71% |
70% |
-1% |
| Complexity | 15796 |
15977 |
181 ⛔ |
The following classes have significant coverage changes.
| File | Line coverage change | Branch coverage change | Complexity change |
|---|---|---|---|
| Datadog.Trace.Debugger.Instrumentation.MethodMetadataInfoFactory | -20% ⛔ |
0% ✔️ |
1 ⛔ |
| Datadog.Trace.Ci.Coverage.DefaultCoverageEventHandler | 0% ✔️ |
-30% ⛔ |
33 ⛔ |
| Datadog.Trace.Ci.CIVisibility | 5% ✔️ |
6% ✔️ |
0 ✔️ |
| Datadog.Trace.Ci.Coverage.CoverageContextContainer | 17% ✔️ |
-75% ⛔ |
3 ⛔ |
The following classes were added in #3079:
| File | Line coverage | Branch coverage | Complexity |
|---|---|---|---|
| Datadog.Trace.Ci.Coverage.CoverageReporter`1 | 0% |
0% |
13 |
| Datadog.Trace.Ci.Coverage.Metadata.ModuleCoverageMetadata | 0% |
100% |
4 |
| Datadog.Trace.Ci.Coverage.MethodValues | 0% |
0% |
2 |
| Datadog.Trace.Ci.Coverage.ModuleValue | 0% |
0% |
2 |
| Datadog.Trace.Ci.Coverage.TypeValues | 0% |
0% |
2 |
| ...And 3 more |
2 classes were removed from Datadog.Trace in #3079
View the full reports for further details:
Summary of changes
Adding the ability to add probes on async methods for all supported .NET runtimes (on both Windows and Linux).
Reason for change
The .NET Live Debugger has so-far only supported adding probes on non-async method. This is a big gap :)
Implementation details
There are a few differences between the regular method probes implementation to the async one.
4.1. Some of the original locals (from the kick off method) are hoisted onto a heap-allocated closure, whereas others which do not persist across invocations, are defined as ‘regular’ locals on the stack.
4.2. Some of the reference-type hoisted locals are nullified and value-type are set to default right before method leave.
4.3. Several "async machinery bookkeeping" locals that aren’t related to the original kick off method, are added as state machine fields or as locals.
When the user requests to put a probe on an asynchronous method, several steps occur:
MoveNextmethod from the appropriate state machine object and ask to put the probe on it instead of the original method - the "kick-off" method.awaitoperation, and should not capture the method parameter values as we do the first time around).When the instrumentation request occurs, we obtain the return type from the task object of the original async method. If it is not
Task<T>then the return type isSystem.Void. Obviously referring to the return type of the original method, theMoveNextmethod always returnsSystem.Void.The instrumentation is divided into two parts:
The first part is the method entry. We call to
AsyncMethodDebuggerInvoker.BeginMethodand pass in the state machine type, thethisobject, several more parameters and the field we added to the state machine object in step 1. We pass this field by ref.Inside
BeginMethod, we check that boolean field value, whether this is the first entry to the method or not. If this is not the first entry, we return from the method immediately and return anAsyncMethodDebuggerStateobject that we save in anAsyncLocalfield.If this is the first entry to the method, we create the
AsyncMethodDebuggerStateobject and save in it, among other things, the kick-off method (the original asynchronous method) and its parent type.In addition, we extract the arguments of the kick-off method from the state machine object as well as the local variables that live in the state machine object. We then capture the
thisobject of the original kick-off method (as a reminder, we are now running inside the state machine object, not in the original method, so we need to take care of getting the originalthis), and the arguments of the original method, and then return theAsyncMethodDebuggerStateobject.The second part is the method exit. To know when is the final exit from the
MoveNextmethod we take advantage of the fact that an async method can only finish its work in one of two cases: In case it ran all the way to the end, there will be a call toSetResultat the end of the method, and in case an unhandled exception was thrown, there will be a call toSetException.So we add the call to
AsyncMethodDebuggerInvoker.EndMethodin both these places.The difference between them is that in the case of an exception, we call an overload that does not return a value (returns a
DebuggerReturnand not aDebuggerReturn<T>) and in the case of aSetResultwe call an overload that returns a value (unless of course the original method was anasync voidmethod).Within
EndMethodwe necessarily know that we have finished running the state machine so we collect everything needed (arguments hoisted in the state machine object, local variables - hoisted or not hoisted, thethisobject of the original method) and we then finally upload a debugger snapshot.Without going into too much detail and actual lines of code, this is a pretty accurate description of what's going on.
The code after the instrumentation will look like this:
Test Coverage
Tests have been added that ensure we properly capture debugger snapshots in the following scenarios:
Task<T>TaskTask.Run