[Debugger] Stabilized the instrumentation of Method Probes and Line Probes by GreenMatan · Pull Request #3164 · DataDog/dd-trace-dotnet

GreenMatan · 2022-09-04T10:57:16Z

Summary of changes

The Exploration Tests revealed numerous InvalidProgramException & BadImageFormatException & TypeLoadException (and more) that occurred due to faulty instrumentation of the Live Debugger. This PR introduces fixes to all of them.

Reason for change

We are starting to evaluate the Live Debugger with beta testers, it's crucial to have resilient instrumentation that will NEVER break customer code what-so-ever.

Implementation details

Avoid instrumenting methods with ref return value (Internal Jira Ticket: DEBUG-1065).
Avoid instrumenting static and non-static c'tors (due to InvalidProgramException that occur when we attempt to place a Method Probe on c'tors that reside in an assembly that is marked as 'Transparent Code' security level as part of CAS which only applicable in .NET Framework). To be on the safe side I disabled the instrumentation of c'tors regardless of the .NET Runtime in use (.NET Framework / .NET Core). (Internal Jira Ticket: DEBUG-1063).
Fixed stack imbalance that happened when the compiler optimized branching opcodes and uses values already stored in the stack when it does a jump to the ret instruction.
Fixes of various faulty instrumentation related to generic methods due to usage of invalid/inaccurate tokens (mainly around load of this).
Fixed Exception Handling Clauses position in the Exception Clause Table - Adhering to the .NET Specification (ECMA 335). Which now allows us to place line probes on async methods without facing InvalidProgramException.
Fixed a memory leak in ProbeRateLimiter (exposed by the Exploration Tests).
Fixed Line probe snapshot serialization issues.
Fixed MissingFieldException that happened because we were adding our State Machine's boolean field (IsReEnter) at incorrect timing (when the probe was applied, which sometime was after the containing module was loaded) - now I'm adding it on ModuleLoadFinished to all Compiler-Generated State Machines (async transformation) that can be found.
Improved Line Probe document searching to support Async Methods scenarios.
Avoid instrumenting methods the Tracer has already instrumented (instrumentation competition between the Tracer and the Debugger).

Test coverage

For the c'tors: EmptyCtorTest and NonEmptyCtorTest are in place to make sure we avoid instrumenting those.
For the 'Transparent Code': CtorTransparentCodeTest (that uses a new dependency Samples.Probes.External that creates an assembly that is marked as Transparent using SecurityTransparentAttribute).
'ref' return is covered by a new test named GenericRefReturnTest.
The rest are covered by the Exploration Tests of the Live Debugger (that are now enabled).

zacharycmontoya · 2022-09-19T18:35:18Z

2. Avoid instrumenting static and non-static c'tors (due to InvalidProgramException that occur when we attempt to place a Method Probe on c'tors that reside in an assembly that is marked as 'Transparent Code' security level as part of CAS which only applicable in .NET Framework). To be on the safe side I disabled the instrumentation of c'tors regardless of the .NET Runtime in use (.NET Framework / .NET Core). (Internal Jira Ticket: DEBUG-1063).

Just double-checking, is the disabling of c'tor instrumentation only for live debugger instrumentation? We have a couple of tracer instrumentations that rely on instrumenting the c'tor of a library type

zacharycmontoya

LGTM in regards to the Datadog.Tracer.Native files that are shared with the Tracer

GreenMatan · 2022-09-19T22:22:15Z

Avoid instrumenting static and non-static c'tors (due to InvalidProgramException that occur when we attempt to place a Method Probe on c'tors that reside in an assembly that is marked as 'Transparent Code' security level as part of CAS which only applicable in .NET Framework). To be on the safe side I disabled the instrumentation of c'tors regardless of the .NET Runtime in use (.NET Framework / .NET Core). (Internal Jira Ticket: DEBUG-1063).

Just double-checking, is the disabling of c'tor instrumentation only for live debugger instrumentation? We have a couple of tracer instrumentations that rely on instrumenting the c'tor of a library type

@zacharycmontoya

Yep, I added this check in our rewriter:

dd-trace-dotnet/tracer/src/Datadog.Tracer.Native/debugger_method_rewriter.cpp

Line 1224 in 97d3033

    
           if (retTypeFlags & TypeFlagByRef || caller->name == WStr(".ctor") || caller->name == WStr(".cctor"))

tonyredondo

LGTM ( I reviewed the tracer's C++ parts )

…gger to instrument a method

…ues + memory leak in ProbeRateLimiter + Line probe document invalid searching + Increased blamre dump from 1 min to 60 min + activated several tests

…Comment + disabled the line probe test of `AsyncInstanceMethod`

andrewlock · 2022-09-20T10:33:52Z

Benchmarks Report 🐌

Benchmarks for #3164 compared to master:

All benchmarks have the same speed
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.AgentWriterBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`WriteAndFlushEnrichedTraces`	net472	715μs	523ns	1.96μs	0.357	3.18 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	467μs	190ns	735ns	0	2.59 KB
#3164	`WriteAndFlushEnrichedTraces`	net472	716μs	528ns	2.04μs	0.357	3.18 KB
#3164	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	466μs	283ns	1.06μs	0	2.58 KB

Benchmarks.Trace.AppSecBodyBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`AllCycleSimpleBody`	net472	182ns	0.15ns	0.56ns	0.0676	9.26E-05	425 B
master	`AllCycleSimpleBody`	netcoreapp3.1	238ns	0.258ns	0.999ns	0.00578	0	424 B
master	`AllCycleMoreComplexBody`	net472	183ns	0.14ns	0.54ns	0.0637	0	401 B
master	`AllCycleMoreComplexBody`	netcoreapp3.1	237ns	0.328ns	1.27ns	0.00544	0	400 B
master	`BodyExtractorSimpleBody`	net472	257ns	0.349ns	1.35ns	0.0573	0	361 B
master	`BodyExtractorSimpleBody`	netcoreapp3.1	218ns	0.212ns	0.821ns	0.00373	0	272 B
master	`BodyExtractorMoreComplexBody`	net472	14.7μs	11.2ns	42.1ns	1.21	0.0147	7.62 KB
master	`BodyExtractorMoreComplexBody`	netcoreapp3.1	12.1μs	15.1ns	56.4ns	0.0906	0	6.75 KB
#3164	`AllCycleSimpleBody`	net472	200ns	0.165ns	0.618ns	0.0676	0	425 B
#3164	`AllCycleSimpleBody`	netcoreapp3.1	237ns	0.216ns	0.809ns	0.00576	0	424 B
#3164	`AllCycleMoreComplexBody`	net472	180ns	0.159ns	0.618ns	0.0637	0	401 B
#3164	`AllCycleMoreComplexBody`	netcoreapp3.1	234ns	0.437ns	1.69ns	0.00541	0	400 B
#3164	`BodyExtractorSimpleBody`	net472	256ns	0.186ns	0.722ns	0.0573	0	361 B
#3164	`BodyExtractorSimpleBody`	netcoreapp3.1	219ns	0.174ns	0.652ns	0.00366	0	272 B
#3164	`BodyExtractorMoreComplexBody`	net472	14.7μs	20ns	77.4ns	1.21	0.022	7.62 KB
#3164	`BodyExtractorMoreComplexBody`	netcoreapp3.1	12.3μs	10.6ns	41.2ns	0.0925	0	6.75 KB

Benchmarks.Trace.AspNetCoreBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendRequest`	net472	0ns	0ns	0ns	0	0	0 b
master	`SendRequest`	netcoreapp3.1	180μs	160ns	618ns	0.271	0	20.58 KB
#3164	`SendRequest`	net472	0ns	0ns	0ns	0	0	0 b
#3164	`SendRequest`	netcoreapp3.1	182μs	256ns	993ns	0.273	0.091	20.59 KB

Benchmarks.Trace.DbCommandBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`ExecuteNonQuery`	net472	1.85μs	0.961ns	3.72ns	0.15	0.00093	947 B
master	`ExecuteNonQuery`	netcoreapp3.1	1.4μs	0.394ns	1.42ns	0.0127	0	936 B
#3164	`ExecuteNonQuery`	net472	1.84μs	0.967ns	3.75ns	0.15	0.00092	947 B
#3164	`ExecuteNonQuery`	netcoreapp3.1	1.41μs	0.742ns	2.87ns	0.0127	0	936 B

Benchmarks.Trace.ElasticsearchBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net472	2.6μs	1.4ns	5.41ns	0.182	1.16 KB
master	`CallElasticsearch`	netcoreapp3.1	1.52μs	0.975ns	3.65ns	0.0145	1.1 KB
master	`CallElasticsearchAsync`	net472	2.67μs	1.83ns	6.86ns	0.204	1.29 KB
master	`CallElasticsearchAsync`	netcoreapp3.1	1.63μs	1.22ns	4.72ns	0.0163	1.22 KB
#3164	`CallElasticsearch`	net472	2.62μs	1.15ns	4.44ns	0.184	1.16 KB
#3164	`CallElasticsearch`	netcoreapp3.1	1.57μs	2.25ns	8.42ns	0.0148	1.1 KB
#3164	`CallElasticsearchAsync`	net472	2.62μs	1.78ns	6.91ns	0.205	1.29 KB
#3164	`CallElasticsearchAsync`	netcoreapp3.1	1.68μs	1.07ns	4ns	0.0159	1.22 KB

Benchmarks.Trace.GraphQLBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net472	2.77μs	2.43ns	9.41ns	0.226	1.42 KB
master	`ExecuteAsync`	netcoreapp3.1	1.77μs	4.66ns	18ns	0.0186	1.34 KB
#3164	`ExecuteAsync`	net472	2.81μs	5.05ns	19.6ns	0.225	1.42 KB
#3164	`ExecuteAsync`	netcoreapp3.1	1.76μs	3.52ns	13.6ns	0.0186	1.34 KB

Benchmarks.Trace.HttpClientBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`SendAsync`	net472	5.7μs	12.1ns	46.8ns	0.439	0	2.77 KB
master	`SendAsync`	netcoreapp3.1	3.68μs	8.37ns	32.4ns	0.0357	0	2.6 KB
#3164	`SendAsync`	net472	5.75μs	10.9ns	42.3ns	0.438	0.0029	2.77 KB
#3164	`SendAsync`	netcoreapp3.1	3.65μs	7.9ns	30.6ns	0.0364	0	2.6 KB

Benchmarks.Trace.ILoggerBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	3.22μs	3.61ns	14ns	0.287	1.81 KB
master	`EnrichedLog`	netcoreapp3.1	2.58μs	1.52ns	5.67ns	0.0244	1.85 KB
#3164	`EnrichedLog`	net472	3.11μs	4.07ns	15.7ns	0.287	1.81 KB
#3164	`EnrichedLog`	netcoreapp3.1	2.47μs	1.04ns	4.04ns	0.0246	1.85 KB

Benchmarks.Trace.Log4netBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	150μs	153ns	594ns	0.67	0.223	4.66 KB
master	`EnrichedLog`	netcoreapp3.1	115μs	86.6ns	324ns	0.0576	0	4.49 KB
#3164	`EnrichedLog`	net472	151μs	222ns	862ns	0.677	0.226	4.66 KB
#3164	`EnrichedLog`	netcoreapp3.1	118μs	135ns	524ns	0	0	4.49 KB

Benchmarks.Trace.NLogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	5.69μs	10.9ns	42.3ns	0.567	0.00289	3.59 KB
master	`EnrichedLog`	netcoreapp3.1	4.24μs	7.25ns	27.1ns	0.0549	0	3.91 KB
#3164	`EnrichedLog`	net472	5.7μs	11.4ns	44.2ns	0.57	0.00288	3.59 KB
#3164	`EnrichedLog`	netcoreapp3.1	4.32μs	9.44ns	36.6ns	0.0523	0	3.91 KB

Benchmarks.Trace.RedisBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`SendReceive`	net472	2.24μs	2.66ns	9.58ns	0.218	1.37 KB
master	`SendReceive`	netcoreapp3.1	1.82μs	0.781ns	3.03ns	0.0183	1.32 KB
#3164	`SendReceive`	net472	2.25μs	1.52ns	5.89ns	0.218	1.37 KB
#3164	`SendReceive`	netcoreapp3.1	1.8μs	0.593ns	2.14ns	0.0179	1.32 KB

Benchmarks.Trace.SerilogBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	5.03μs	2.22ns	8.59ns	0.354	2.23 KB
master	`EnrichedLog`	netcoreapp3.1	4.29μs	3.38ns	12.2ns	0.0235	1.8 KB
#3164	`EnrichedLog`	net472	5.07μs	3.32ns	12.9ns	0.353	2.23 KB
#3164	`EnrichedLog`	netcoreapp3.1	4.41μs	8.34ns	32.3ns	0.0241	1.8 KB

Benchmarks.Trace.SpanBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net472	1.22μs	0.61ns	2.36ns	0.129	810 B
master	`StartFinishSpan`	netcoreapp3.1	921ns	0.215ns	0.832ns	0.0102	760 B
master	`StartFinishScope`	net472	1.43μs	1.01ns	3.9ns	0.141	891 B
master	`StartFinishScope`	netcoreapp3.1	1.13μs	0.479ns	1.79ns	0.0119	880 B
#3164	`StartFinishSpan`	net472	1.22μs	0.684ns	2.65ns	0.128	810 B
#3164	`StartFinishSpan`	netcoreapp3.1	929ns	0.549ns	2.13ns	0.0103	760 B
#3164	`StartFinishScope`	net472	1.47μs	2.4ns	8.66ns	0.141	891 B
#3164	`StartFinishScope`	netcoreapp3.1	1.06μs	0.571ns	2.21ns	0.0122	880 B

Benchmarks.Trace.TraceAnnotationsBenchmark - Same speed ✔️ Same allocations ✔️

Raw results

Branch	Method	Toolchain	Mean	StdError	StdDev	Gen 0	Allocated
master	`RunOnMethodBegin`	net472	1.47μs	0.994ns	3.85ns	0.141	891 B
master	`RunOnMethodBegin`	netcoreapp3.1	1.18μs	0.512ns	1.98ns	0.0118	880 B
#3164	`RunOnMethodBegin`	net472	1.52μs	0.949ns	3.67ns	0.142	891 B
#3164	`RunOnMethodBegin`	netcoreapp3.1	1.12μs	0.349ns	1.26ns	0.0118	880 B

andrewlock · 2022-09-20T12:23:06Z

Code Coverage Report 📊

⚠️ Merging #3164 into master will will decrease line coverage by 4%
⚠️ Merging #3164 into master will will decrease branch coverage by 2%
⛔ Merging #3164 into master will will increase complexity by 14

	master	#3164	Change
Lines	`17963` / `24889`	`17005` / `24903`
Lines %	`72%`	`68%`	`-4%` ⚠️
Branches	`10472` / `15254`	`10235` / `15270`
Branches %	`69%`	`67%`	`-2%` ⚠️
Complexity	`16477`	`16491`	`14` ⛔

View the full report for further details:

Datadog.Trace Breakdown ⚠️

	master	#3164	Change
Lines %	`72%`	`68%`	`-4%` ⚠️
Branches %	`69%`	`67%`	`-2%` ⚠️
Complexity	`16477`	`16491`	`14` ⛔

The following classes have significant coverage changes.

File	Line coverage change	Branch coverage change	Complexity change
Datadog.Trace.Debugger.PInvoke.NativeMethodProbeDefinition	`-100%` ⛔	`-100%` ⛔	`0` ✔️
Datadog.Trace.Debugger.Sink.SnapshotSink	`-100%` ⛔	`-100%` ⛔	`0` ✔️
Datadog.Trace.Debugger.Snapshots.LazySnapshotSerializerFieldsAndPropsSelector	`-100%` ⛔	`-100%` ⛔	`0` ✔️
Datadog.Trace.Debugger.Snapshots.DebuggerSnapshotCreator	`-100%` ⛔	`-68%` ⛔	`1` ⛔
BoundLineProbeLocation	`-100%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Debugger.CapturedLines	`-100%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Debugger.Instrumentation.DebuggerReturn	`-100%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Debugger.Instrumentation.MethodMetadataInfo	`-100%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Debugger.Models.LineProbeResolveResult	`-100%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Debugger.PInvoke.NativeLineProbeDefinition	`-100%` ⛔	`0%` ✔️	`0` ✔️
...And 74 more

View the full reports for further details:

github-actions Bot added the area:debugger label Sep 4, 2022

GreenMatan force-pushed the matang/fixing-instrumentation-errors branch from 3903b17 to 86b5da9 Compare September 4, 2022 11:00