[2.0] Add modified WCF CallTarget instrumentation via opt-in environment variable #2041

zacharycmontoya · 2021-11-15T21:38:21Z

Cherry-picks the changes from #1992

Additional changes:

Move CreateScope method from ChannelHandlerIntegration.cs to WcfCommon.cs
Remove testing of CallSite codepaths in WcfTests

@DataDog/apm-dotnet

tracer/build/_build/PrepareRelease/GenerateIntegrationDefinitions.cs

andrewlock · 2021-11-16T18:11:48Z

tracer/src/Datadog.Trace.ClrProfiler.Native/cor_profiler.cpp

+    int numArgs = useCustomArgumentsTargetMethodArguments
+                    ? (int) methodArgumentsToLoad.size()
+                    : caller->method_signature.NumberOfArguments();


Just speculating, but do we expect any performance impact (hopefully improvement) from not passing all the arguments to our integrations? e.g. should we adopt this as "standard" for our integrations, where we only pass the arguments we strictly need?

I'm not sure how much we would save from avoiding unnecessary ldarg IL instructions, but maybe it could reduce the amount of generic types are created at runtime? This would be good to benchmark at some point

andrewlock · 2021-11-16T18:13:54Z

tracer/test/test-applications/integrations/Samples.Wcf/Client/Startup.cs

+
+                exceptionsSeen += await Invoke_ServerSyncAdd_Endpoints(calculator);
+                exceptionsSeen += await Invoke_ServerTaskAdd_Endpoints(calculator);
+                // exceptionsSeen += await Invoke_ServerAsyncAdd_Endpoints(calculator); // Ignore the async server endpoint because it is flaky in CI right now


Do we have any idea why it's flaky?

No I don't understand yet why it's flaky. When running this locally, I got consistent results run after run where all 3 spans were created. In CI, there'd be inconsistent results where 1-3 could be missing

lucaspimentel · 2021-11-19T16:58:10Z

We rebased release/2.0 on master and deleted that branch. Your PR is now targeting master instead. Please use the following commands to rebase your commits onto master and fix this PR:

get checkout zach/release20/wcf-request-message-fix
git rebase release/2.0 --onto origin/master
git push origin --force-with-lease

Additional changes include: - Move CreateScope method from ChannelHandlerIntegration.cs to WcfCommon.cs Strip out all CallTarget changes and use the new CallTarget ByRef instrumentation to instrument WCF methods which have out parameters (thanks Tony!)

tonyredondo

LGTM! nit: any reason to not use ducktyping in this integration?

tracer/src/Datadog.Trace/ClrProfiler/AutoInstrumentation/Wcf/SyncMethodInvokerIntegration.cs

zacharycmontoya · 2021-11-30T17:17:04Z

LGTM! nit: any reason to not use ducktyping in this integration?

I wanted to limit the changes I made to just the integration points instead of doing a refactor of the WCF code, in order to minimize risk. The WCF code could definitely benefit from ducktyping but I'm thinking we can do that separately

andrewlock · 2021-11-30T18:38:54Z

Code Coverage Report 📊

✔️ Merging #2041 into master will not change line coverage
✔️ Merging #2041 into master will not change branch coverage
⛔ Merging #2041 into master will will increase complexity by 33

	master	#2041	Change
Lines	`8912` / `12391`	`8941` / `12425`
Lines %	`72%`	`72%`	`0%` ✔️
Branches	`3973` / `5979`	`3999` / `6009`
Branches %	`66%`	`67%`	`0%` ✔️
Complexity	`7109`	`7142`	`33` ⛔

View the full report for further details:

Datadog.Trace Breakdown ✔️

	master	#2041	Change
Lines %	`72%`	`72%`	`0%` ✔️
Branches %	`66%`	`67%`	`0%` ✔️
Complexity	`7109`	`7142`	`33` ⛔

The following classes have significant coverage changes.

File	Line coverage change	Branch coverage change	Complexity change
Datadog.Trace.ClrProfiler.AutoInstrumentation.Couchbase.IIOServiceExecuteIntegrationBis	`-100%` ⛔	`0%` ✔️	`0` ✔️
Datadog.Trace.Ci.Agent.CIAgentWriter	`-10%` ⛔	`-21%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Testing.NUnit.NUnitCompositeWorkItemSkipChildrenIntegration	`-8%` ⛔	`-8%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Http.WebRequest.HttpWebRequest_BeginGetRequestStream_Integration	`14%` ✔️	`20%` ✔️	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Wcf.ChannelHandlerIntegration	`15%` ✔️	`33%` ✔️	`-18` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Http.WebRequest.HttpWebRequest_EndGetResponse_Integration	`29%` ✔️	`23%` ✔️	`0` ✔️

The following classes were added in #2041:

File	Line coverage	Branch coverage	Complexity
Datadog.Trace.ClrProfiler.AutoInstrumentation.Wcf.AsyncMethodInvoker_InvokeBegin_Integration	`0%`	`0%`	`8`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Wcf.AsyncMethodInvoker_InvokeEnd_Integration	`0%`	`100%`	`1`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Wcf.SyncMethodInvokerIntegration	`100%`	`88%`	`9`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Wcf.TaskMethodInvokerIntegration	`100%`	`88%`	`9`
Datadog.Trace.ClrProfiler.AutoInstrumentation.Wcf.WcfCommon	`85%`	`65%`	`22`

View the full reports for further details:

lucaspimentel · 2021-11-30T18:59:07Z

tracer/src/Datadog.Trace/ClrProfiler/AutoInstrumentation/Wcf/WcfCommon.cs

+                object requestHeaders = requestMessage.GetProperty<object>("Headers").GetValueOrDefault();
+                string action = requestHeaders.GetProperty<string>("Action").GetValueOrDefault();
+                Uri requestHeadersTo = requestHeaders.GetProperty<Uri>("To").GetValueOrDefault();


Don't we want to use duck typing going forwards instead of GetProperty<T>(string)?

(I'm surprised we haven't removed those extension methods yet)

Saw your comment later: #2041 (comment)

lucaspimentel · 2021-11-30T19:02:39Z

tracer/src/Datadog.Trace/Configuration/ImmutableTracerSettings.cs

+        /// Gets a value indicating whether to enable the updated WCF instrumentation that delays execution
+        /// until later in the WCF pipeline when the WCF server exception handling is established.
+        /// </summary>
+        internal bool DelayWcfInstrumentationEnabled { get; }


Grammatically, either WcfInstrumentationDelayEnabled or DelayedWcfInstrumentationEnabled sounds better to me. If this is only meant as a temporary feature flag, then my level of care is lower.

We have one customer using this already (via environment variable DD_TRACE_DELAY_WCF_INSTRUMENTATION_ENABLED) so I'd rather not change it. Fingers crossed we can make this the default behavior once we figure out some missing spans

lucaspimentel

LGTM. Left a non-blocking comment or two.

andrewlock · 2021-11-30T19:34:37Z

Benchmarks Report 🐌

Benchmarks for #2041 compared to master:

1 benchmarks are faster, with geometric mean 1.176
2 benchmarks are slower, with geometric mean 1.273
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	Error	StdDev	Allocated
master	`WriteAndFlushEnrichedTraces`	net472	934.4 μs	18.21 μs	17.88 μs	3.09 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	729.6 μs	12.82 μs	22.79 μs	2.51 KB
#2041	`WriteAndFlushEnrichedTraces`	net472	949.3 μs	18.77 μs	38.33 μs	3.09 KB
#2041	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	750.9 μs	14.16 μs	15.74 μs	2.51 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendRequest`	net472	0.0000 ns	0.0000 ns	0.0000 ns	0.0000	0 B
master	`SendRequest`	netcoreapp3.1	282,045.7601 ns	5,230.5325 ns	4,892.6433 ns	0.1374	19617 B
#2041	`SendRequest`	net472	0.0000 ns	0.0000 ns	0.0000 ns	0.0000	0 B
#2041	`SendRequest`	netcoreapp3.1	279,861.5218 ns	5,545.5297 ns	5,933.6546 ns	0.1377	19617 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev
master	`ExecuteNonQuery`	net472	343.1 ns	6.79 ns	10.37 ns
master	`ExecuteNonQuery`	netcoreapp3.1	291.8 ns	5.64 ns	8.62 ns
#2041	`ExecuteNonQuery`	net472	343.5 ns	6.89 ns	6.77 ns
#2041	`ExecuteNonQuery`	netcoreapp3.1	286.5 ns	5.21 ns	4.88 ns

Benchmarks.Trace.ElasticsearchBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #2041

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ElasticsearchBenchmark.CallElasticsearchAsync‑net472	1.408	3,225.78	4,540.78

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net472	3.110 μs	0.0608 μs	0.0676 μs	0.1284	827 B
master	`CallElasticsearch`	netcoreapp3.1	1.614 μs	0.0316 μs	0.0280 μs	0.0106	768 B
master	`CallElasticsearchAsync`	net472	3.251 μs	0.0614 μs	0.0575 μs	0.1499	963 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.717 μs	0.0241 μs	0.0226 μs	0.0126	888 B
#2041	`CallElasticsearch`	net472	3.213 μs	0.0611 μs	0.0750 μs	0.1286	827 B
#2041	`CallElasticsearch`	netcoreapp3.1	1.603 μs	0.0317 μs	0.0494 μs	0.0109	768 B
#2041	`CallElasticsearchAsync`	net472	4.560 μs	0.0890 μs	0.0832 μs	0.1492	963 B
#2041	`CallElasticsearchAsync`	netcoreapp3.1	1.662 μs	0.0228 μs	0.0213 μs	0.0124	888 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net472	3.447 μs	0.0660 μs	0.0706 μs	0.1688	1083 B
master	`ExecuteAsync`	netcoreapp3.1	1.844 μs	0.0235 μs	0.0220 μs	0.0144	1008 B
#2041	`ExecuteAsync`	net472	3.598 μs	0.0710 μs	0.0697 μs	0.1691	1083 B
#2041	`ExecuteAsync`	netcoreapp3.1	1.817 μs	0.0243 μs	0.0190 μs	0.0141	1008 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendAsync`	net472	6.058 μs	0.1185 μs	0.2106 μs	0.3487	2.19 KB
master	`SendAsync`	netcoreapp3.1	4.440 μs	0.0538 μs	0.0503 μs	0.0283	2.09 KB
#2041	`SendAsync`	net472	6.324 μs	0.1156 μs	0.1800 μs	0.3490	2.19 KB
#2041	`SendAsync`	netcoreapp3.1	4.320 μs	0.0837 μs	0.1352 μs	0.0294	2.09 KB

Benchmarks.Trace.ILoggerBenchmark - Faster 🎉 Same allocations ✔️

Faster 🎉 in #2041

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.ILoggerBenchmark.EnrichedLog‑net472	1.176	4,595.36	3,906.72

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	4.604 μs	0.0488 μs	0.0433 μs	0.2852	1.79 KB
master	`EnrichedLog`	netcoreapp3.1	3.798 μs	0.0747 μs	0.0734 μs	0.0275	1.94 KB
#2041	`EnrichedLog`	net472	3.916 μs	0.0757 μs	0.0984 μs	0.2872	1.79 KB
#2041	`EnrichedLog`	netcoreapp3.1	3.879 μs	0.0472 μs	0.0394 μs	0.0270	1.94 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Gen 1	Allocated
master	`EnrichedLog`	net472	182.4 μs	3.45 μs	5.06 μs	0.7013	0.2630	5.23 KB
master	`EnrichedLog`	netcoreapp3.1	146.5 μs	2.06 μs	1.93 μs	0.0000	0.0000	5.05 KB
#2041	`EnrichedLog`	net472	176.2 μs	3.51 μs	4.31 μs	0.6859	0.2572	5.23 KB
#2041	`EnrichedLog`	netcoreapp3.1	146.8 μs	2.43 μs	2.28 μs	0.0000	0.0000	5.05 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	11.31 μs	0.194 μs	0.181 μs	0.8496	5.31 KB
master	`EnrichedLog`	netcoreapp3.1	10.10 μs	0.150 μs	0.140 μs	0.0897	6.28 KB
#2041	`EnrichedLog`	net472	11.324 μs	0.2261 μs	0.2005 μs	0.8524	5.31 KB
#2041	`EnrichedLog`	netcoreapp3.1	9.984 μs	0.1902 μs	0.1868 μs	0.0941	6.28 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendReceive`	net472	2.139 μs	0.0331 μs	0.0310 μs	0.1542	987 B
master	`SendReceive`	netcoreapp3.1	1.988 μs	0.0239 μs	0.0223 μs	0.0138	984 B
#2041	`SendReceive`	net472	2.199 μs	0.0432 μs	0.0722 μs	0.1549	987 B
#2041	`SendReceive`	netcoreapp3.1	1.977 μs	0.0281 μs	0.0249 μs	0.0133	984 B

Benchmarks.Trace.SerilogBenchmark - Slower ⚠️ Same allocations ✔️

Slower ⚠️ in #2041

Benchmark	diff/base	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.SerilogBenchmark.EnrichedLog‑netcoreapp3.1	1.151	7,043.97	8,110.68

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	7.834 μs	0.1542 μs	0.1443 μs	0.4461	2.8 KB
master	`EnrichedLog`	netcoreapp3.1	7.011 μs	0.0950 μs	0.1167 μs	0.0374	2.61 KB
#2041	`EnrichedLog`	net472	8.085 μs	0.1604 μs	0.2086 μs	0.4471	2.8 KB
#2041	`EnrichedLog`	netcoreapp3.1	8.200 μs	0.1616 μs	0.3075 μs	0.0379	2.61 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net472	925.1 ns	18.53 ns	25.98 ns	0.0678	433 B
master	`StartFinishSpan`	netcoreapp3.1	903.8 ns	13.90 ns	12.32 ns	0.0057	432 B
master	`StartFinishScope`	net472	1,080.7 ns	18.28 ns	32.50 ns	0.0807	514 B
master	`StartFinishScope`	netcoreapp3.1	1,021.1 ns	17.67 ns	15.66 ns	0.0075	552 B
#2041	`StartFinishSpan`	net472	895.6 ns	16.98 ns	14.18 ns	0.0680	433 B
#2041	`StartFinishSpan`	netcoreapp3.1	886.2 ns	14.07 ns	12.47 ns	0.0061	432 B
#2041	`StartFinishScope`	net472	1,064.8 ns	20.99 ns	20.62 ns	0.0803	514 B
#2041	`StartFinishScope`	netcoreapp3.1	1,021.4 ns	14.12 ns	13.21 ns	0.0076	552 B

zacharycmontoya added type:bug area:automatic-instrumentation Automatic instrumentation managed C# code (Datadog.Trace.ClrProfiler.Managed) area:call-target labels Nov 15, 2021

zacharycmontoya self-assigned this Nov 15, 2021

zacharycmontoya requested a review from a team as a code owner November 15, 2021 21:38

This comment has been minimized.

Sign in to view

andrewlock approved these changes Nov 16, 2021

View reviewed changes

This comment has been minimized.

Sign in to view

lucaspimentel deleted the branch master November 19, 2021 16:28

lucaspimentel closed this Nov 19, 2021

lucaspimentel reopened this Nov 19, 2021

lucaspimentel changed the base branch from release/2.0 to master November 19, 2021 16:35

lucaspimentel requested review from a team as code owners November 19, 2021 16:35

zacharycmontoya added this to the 2.0 milestone Nov 22, 2021

zacharycmontoya force-pushed the zach/release20/wcf-request-message-fix branch from 59aa8f2 to 3724bd9 Compare November 22, 2021 21:44

This comment has been minimized.

Sign in to view

zacharycmontoya added 2 commits November 29, 2021 14:42

Remove testing of CallSite codepaths in WcfTests

907d39e

zacharycmontoya force-pushed the zach/release20/wcf-request-message-fix branch from 3724bd9 to 907d39e Compare November 29, 2021 22:42

This comment has been minimized.

Sign in to view

tonyredondo approved these changes Nov 30, 2021

View reviewed changes

tracer/src/Datadog.Trace/ClrProfiler/AutoInstrumentation/Wcf/SyncMethodInvokerIntegration.cs Outdated Show resolved Hide resolved

Change SyncMethodInvokerIntegration to use ref instead of out

ec1f9de

lucaspimentel reviewed Nov 30, 2021

View reviewed changes

lucaspimentel approved these changes Nov 30, 2021

View reviewed changes

zacharycmontoya merged commit 8529387 into master Nov 30, 2021

zacharycmontoya deleted the zach/release20/wcf-request-message-fix branch November 30, 2021 19:39

github-actions bot modified the milestones: 2.0, vNext Nov 30, 2021

andrewlock modified the milestones: vNext, 2.0 Dec 1, 2021

pierotibou modified the milestones: 2.0, vNext Dec 10, 2021

[2.0] Add modified WCF CallTarget instrumentation via opt-in environment variable #2041

[2.0] Add modified WCF CallTarget instrumentation via opt-in environment variable #2041

Uh oh!

Conversation

zacharycmontoya commented Nov 15, 2021

Uh oh!

This comment has been minimized.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

This comment has been minimized.

lucaspimentel commented Nov 19, 2021

Uh oh!

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

tonyredondo left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

zacharycmontoya commented Nov 30, 2021

Uh oh!

andrewlock commented Nov 30, 2021

Code Coverage Report 📊

Datadog.Trace Breakdown ✔️

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lucaspimentel left a comment

Choose a reason for hiding this comment

Uh oh!

andrewlock commented Nov 30, 2021

Benchmarks Report 🐌

Benchmark details

Raw results

Raw results

Raw results

Slower ⚠️ in #2041

Raw results

Raw results

Raw results

Faster 🎉 in #2041

Raw results

Raw results

Raw results

Raw results

Slower ⚠️ in #2041

Raw results

Raw results

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants