Support child actions in aspnet by pierotibou · Pull Request #2139 · DataDog/dd-trace-dotnet

pierotibou · 2021-12-08T08:56:12Z

Currently, when customers used child actions in aspnet, we were actually dropping spans. Indeed, we used to store the scope in HttpContext.Current.Items. With child actions, we were overwriting this scope and thus not closing the span.

I fixed that by adding a stack if we already have a scope in Items. Also, I added a special handling of the resourcename to not override the resourceName in Items when there is already one as this resource is set for the root level span.

Also, this PR enforces the resource name to stick to what was requested in the http request when DD_TRACE_ROUTE_TEMPLATE_RESOURCE_NAMES_ENABLED is enabled.
Jira: APMS-6288

@DataDog/apm-dotnet

andrewlock

Nice elegant solution! A couple of minor comments, but I'm not sure it's working correctly for the "with feature flag" version?

andrewlock · 2021-12-09T16:08:50Z

Benchmarks Report 🐌

Benchmarks for #2139 compared to master:

1 benchmarks are faster, with geometric mean 1.158
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	939.8 μs	18.35 μs	24.50 μs	3.09 KB
master	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	751.2 μs	14.39 μs	12.76 μs	2.51 KB
#2139	`WriteAndFlushEnrichedTraces`	net472	956.7 μs	18.35 μs	18.02 μs	3.09 KB
#2139	`WriteAndFlushEnrichedTraces`	netcoreapp3.1	746.5 μs	7.45 μs	6.60 μ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	295,891.6337 ns	4,677.3909 ns	4,375.2344 ns	0.1478	19594 B
#2139	`SendRequest`	net472	0.0000 ns	0.0000 ns	0.0000 ns	0.0000	0 B
#2139	`SendRequest`	netcoreapp3.1	294,764.2331 ns	4,711.5232 ns	7,051.9861 ns	0.1499	19594 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev
master	`ExecuteNonQuery`	net472	359.4 ns	6.15 ns	5.75 ns
master	`ExecuteNonQuery`	netcoreapp3.1	308.7 ns	4.75 ns	4.45 ns
#2139	`ExecuteNonQuery`	net472	357.6 ns	6.41 ns	5.99 ns
#2139	`ExecuteNonQuery`	netcoreapp3.1	316.1 ns	6.29 ns	6.18 ns

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`CallElasticsearch`	net472	3.302 μs	0.0485 μs	0.0454 μs	0.1277	827 B
master	`CallElasticsearch`	netcoreapp3.1	1.648 μs	0.0311 μs	0.0359 μs	0.0105	768 B
master	`CallElasticsearchAsync`	net472	3.365 μs	0.0659 μs	0.0732 μs	0.1493	963 B
master	`CallElasticsearchAsync`	netcoreapp3.1	1.696 μs	0.0217 μs	0.0203 μs	0.0123	888 B
#2139	`CallElasticsearch`	net472	3.329 μs	0.0634 μs	0.0562 μs	0.1267	827 B
#2139	`CallElasticsearch`	netcoreapp3.1	1.676 μs	0.0307 μs	0.0240 μs	0.0110	768 B
#2139	`CallElasticsearchAsync`	net472	3.397 μs	0.0661 μs	0.0812 μs	0.1499	963 B
#2139	`CallElasticsearchAsync`	netcoreapp3.1	1.778 μs	0.0355 μs	0.0542 μs	0.0120	888 B

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

Faster 🎉 in #2139

Benchmark	base/diff	Base Median (ns)	Diff Median (ns)	Modality
Benchmarks.Trace.GraphQLBenchmark.ExecuteAsync‑net472	1.158	4,178.27	3,608.94

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`ExecuteAsync`	net472	4.157 μs	0.0752 μs	0.0866 μs	0.1675	1083 B
master	`ExecuteAsync`	netcoreapp3.1	1.885 μs	0.0315 μs	0.0279 μs	0.0137	1008 B
#2139	`ExecuteAsync`	net472	3.616 μs	0.0519 μs	0.0433 μs	0.1675	1083 B
#2139	`ExecuteAsync`	netcoreapp3.1	1.879 μs	0.0310 μs	0.0275 μs	0.0142	1008 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`SendAsync`	net472	7.004 μs	0.1397 μs	0.1494 μs	0.3489	2.19 KB
master	`SendAsync`	netcoreapp3.1	4.245 μs	0.0823 μs	0.0769 μs	0.0284	2.09 KB
#2139	`SendAsync`	net472	6.403 μs	0.0709 μs	0.0554 μs	0.3508	2.19 KB
#2139	`SendAsync`	netcoreapp3.1	4.453 μs	0.0713 μs	0.0667 μs	0.0306	2.09 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	4.049 μs	0.0662 μs	0.0586 μs	0.2866	1.79 KB
master	`EnrichedLog`	netcoreapp3.1	4.136 μs	0.0824 μs	0.1442 μs	0.0281	1.94 KB
#2139	`EnrichedLog`	net472	4.167 μs	0.0471 μs	0.0394 μs	0.2874	1.79 KB
#2139	`EnrichedLog`	netcoreapp3.1	4.168 μs	0.0809 μs	0.0757 μs	0.0273	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	187.2 μs	3.62 μs	4.44 μs	0.6540	0.1868	5.23 KB
master	`EnrichedLog`	netcoreapp3.1	154.0 μs	2.48 μs	2.32 μs	0.0000	0.0000	5.05 KB
#2139	`EnrichedLog`	net472	178.4 μs	2.84 μs	2.66 μs	0.7112	0.2667	5.23 KB
#2139	`EnrichedLog`	netcoreapp3.1	151.8 μs	1.95 μs	1.83 μs	0.0745	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	12.34 μs	0.238 μs	0.244 μs	0.8526	5.31 KB
master	`EnrichedLog`	netcoreapp3.1	10.61 μs	0.207 μs	0.203 μs	0.0921	6.28 KB
#2139	`EnrichedLog`	net472	12.75 μs	0.180 μs	0.160 μs	0.8505	5.31 KB
#2139	`EnrichedLog`	netcoreapp3.1	10.70 μs	0.213 μs	0.390 μs	0.0890	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.418 μs	0.0454 μs	0.0402 μs	0.1542	987 B
master	`SendReceive`	netcoreapp3.1	2.267 μs	0.0445 μs	0.0437 μs	0.0139	984 B
#2139	`SendReceive`	net472	2.284 μs	0.0404 μs	0.0378 μs	0.1550	987 B
#2139	`SendReceive`	netcoreapp3.1	2.160 μs	0.0429 μs	0.0877 μs	0.0138	984 B

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`EnrichedLog`	net472	8.576 μs	0.1526 μs	0.1428 μs	0.4456	2.8 KB
master	`EnrichedLog`	netcoreapp3.1	7.120 μs	0.1106 μs	0.1035 μs	0.0385	2.61 KB
#2139	`EnrichedLog`	net472	8.253 μs	0.1638 μs	0.1452 μs	0.4464	2.8 KB
#2139	`EnrichedLog`	netcoreapp3.1	7.509 μs	0.0448 μs	0.0350 μs	0.0373	2.61 KB

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

Raw results

Branch	Method	Toolchain	Mean	Error	StdDev	Gen 0	Allocated
master	`StartFinishSpan`	net472	922.4 ns	18.35 ns	17.16 ns	0.0678	433 B
master	`StartFinishSpan`	netcoreapp3.1	932.6 ns	17.40 ns	29.06 ns	0.0059	432 B
master	`StartFinishScope`	net472	1,132.6 ns	21.52 ns	22.10 ns	0.0807	514 B
master	`StartFinishScope`	netcoreapp3.1	1,077.3 ns	15.99 ns	13.35 ns	0.0076	552 B
#2139	`StartFinishSpan`	net472	933.8 ns	11.35 ns	10.61 ns	0.0681	433 B
#2139	`StartFinishSpan`	netcoreapp3.1	912.5 ns	12.19 ns	11.40 ns	0.0060	432 B
#2139	`StartFinishScope`	net472	1,160.3 ns	22.46 ns	23.06 ns	0.0805	514 B
#2139	`StartFinishScope`	netcoreapp3.1	1,058.1 ns	13.50 ns	12.63 ns	0.0075	552 B

robertpi · 2021-12-21T09:06:54Z

+{
+    internal static class SharedItems
+    {
+        public const string HttpContextPropagatedResourceNameKey = "__Datadog.Trace.ClrProfiler.Managed.AspNetMvcIntegration-aspnet.resourcename";


I don't really understand why this constant is stored here, when it's never used with the PushItem / PopItem mechanism.

It was there and alone in this class in the first place. I decided to use this class as this constant is a key used on the Items dictionary as well.

robertpi · 2021-12-21T09:08:11Z

+            }
+            else
+            {
+                Log.Warning("Trying to push an item in HttpContext.Items but a previous object of unhandled type is already stored there");


You could avoid this warning by removing the generic parameter from this method. As far as I can see, it's only ever used to to store Scope objects.

Changed in 9c0cc8d

robertpi · 2021-12-21T09:10:12Z

        internal const string HttpContextKey = "__Datadog.Trace.ClrProfiler.Integrations.AspNetMvcIntegration";

        private const string OperationName = "aspnet-mvc.request";
+        private const string ChildActionOperationName = "aspnet-mvc.request.child-action";


Does not appear to be used.

Good catch, question is whether:

It should be removed as unused

We should use a different operation name for child actions
I'm pretty sure we discussed it, but can't remember the conclusion 😬

Thanks for catching that Robert. And indeed, we had dedided to use it Andrew.
Fixed in 9c0cc8d

robertpi · 2021-12-21T09:15:32Z

                    if (httpContext is not null)
                    {
-                        httpContext.Items[SharedConstants.HttpContextPropagatedResourceNameKey] = resourceName;
+                        httpContext.Items[SharedItems.HttpContextPropagatedResourceNameKey] = resourceName;


No need to check if the resource name has already been set?

robertpi

Couple of comments, but I think the correction should work.

tonyredondo

I leave a comment but non blocking.

tonyredondo · 2021-12-21T09:17:57Z

+        internal static void PushItem<T>(HttpContext context, string key, T item)
+        {
+            if (context == null)
+            {
+                return;
+            }
+
+            // Storing only the scope by default to avoid allocating a stack if no inner calls are done
+            var existingItem = context.Items[key];
+            if (existingItem is null)
+            {
+                context.Items[key] = item;
+            }
+            else if (existingItem is Stack<T> stack)
+            {
+                stack.Push(item);
+            }
+            else if (existingItem is T previousScope)
+            {
+                var newStack = new Stack<T>();
+                newStack.Push(previousScope);
+                newStack.Push(item);
+                context.Items[key] = newStack;
+            }
+            else
+            {
+                Log.Warning("Trying to push an item in HttpContext.Items but a previous object of unhandled type is already stored there");
+            }
+        }
+
+        internal static T TryPopItem<T>(HttpContext context, string key)
+        {
+            var item = context?.Items[key];
+            if (item is T storedScope)
+            {
+                return storedScope;
+            }
+            else if (item is Stack<T> stack && stack.Count > 0)
+            {
+                return stack.Pop();
+            }
+
+            return default(T);
+        }


I'm not sure it worth having Generics here, you are only using Scope object in the calls, also, this Generic defines the type of the stack, so you cannot change the T type in the same context, forcing you to pass the same T in all calls.

Fixed in 9c0cc8d
I thought initially that I ought to use this for resource names as well and forgot to update afterwards

Having a child action would overwrite the scope stored in items. We thus failed to close all spans leading to missing spans. ResourceName needs a special handling in that case to make sure we don't overwrite the resource name with the child action one.

Co-authored-by: Andrew Lock <[email protected]>

andrewlock · 2021-12-22T11:14:27Z

Code Coverage Report 📊

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

	master	#2139	Change
Lines	`9195` / `12573`	`9207` / `12595`
Lines %	`73%`	`73%`	`0%` ✔️
Branches	`4182` / `6138`	`4198` / `6160`
Branches %	`68%`	`68%`	`0%` ✔️
Complexity	`7335`	`7357`	`22` ⛔

View the full report for further details:

Datadog.Trace Breakdown ✔️

	master	#2139	Change
Lines %	`73%`	`73%`	`0%` ✔️
Branches %	`68%`	`68%`	`0%` ✔️
Complexity	`7335`	`7357`	`22` ⛔

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.ClrProfiler.AutoInstrumentation.Testing.MsTestV2.TestMethodRunnerExecuteIntegration	`-33%` ⛔	`-19%` ⛔	`0` ✔️
Datadog.Trace.Ci.Agent.CIAgentWriter	`-10%` ⛔	`-21%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.Testing.NUnit.NUnitCompositeWorkItemSkipChildrenIntegration	`-8%` ⛔	`-8%` ⛔	`0` ✔️
Datadog.Trace.ClrProfiler.AutoInstrumentation.AspNet.AsyncControllerActionInvoker_EndInvokeAction_Integration	`0%` ✔️	`17%` ✔️	`-2` ✔️

The following classes were added in #2139:

File	Line coverage	Branch coverage	Complexity
Datadog.Trace.AspNet.SharedItems	`95%`	`88%`	`16`

View the full reports for further details:

* Add Child Action in tests to check it breaks * Handle Child actions use case Having a child action would overwrite the scope stored in items. We thus failed to close all spans leading to missing spans. ResourceName needs a special handling in that case to make sure we don't overwrite the resource name with the child action one. * Apply suggestions from code review Co-authored-by: Andrew Lock <[email protected]> * fix trailing whitespaces from github commit * RouteTemplateResourceNamesEnabled works with child actions * implement comments Co-authored-by: Andrew Lock <[email protected]> (cherry picked from commit 3cafe9e)

* Support child actions in aspnet (#2139) * Add Child Action in tests to check it breaks * Handle Child actions use case Having a child action would overwrite the scope stored in items. We thus failed to close all spans leading to missing spans. ResourceName needs a special handling in that case to make sure we don't overwrite the resource name with the child action one. * Apply suggestions from code review Co-authored-by: Andrew Lock <[email protected]> * fix trailing whitespaces from github commit * RouteTemplateResourceNamesEnabled works with child actions * implement comments Co-authored-by: Andrew Lock <[email protected]> (cherry picked from commit 3cafe9e) * Fix build * Fix asp snapshots file names (#2148) * Fix asp snapshots file names * And Owin tests as well * Fix all snapshots files

pierotibou requested a review from a team as a code owner December 8, 2021 08:56

pierotibou added area:tracer The core tracer library (Datadog.Trace, does not include OpenTracing, native code, or integrations) type:bug labels Dec 8, 2021

andrewlock reviewed Dec 8, 2021

View reviewed changes

andrewlock added this to the 2.0 milestone Dec 8, 2021

andrewlock added the area:automatic-instrumentation Automatic instrumentation managed C# code (Datadog.Trace.ClrProfiler.Managed) label Dec 8, 2021

This comment has been minimized.

Sign in to view

pierotibou force-pushed the pierre/missing-spans-mvc-child-actions branch from 306f104 to 2b0498b Compare December 9, 2021 08:21

pierotibou changed the title ~~Handle child actions in aspnet~~ Support child actions in aspnet Dec 9, 2021

pierotibou changed the base branch from master to pierre/fix-snapshots December 9, 2021 09:23

Base automatically changed from pierre/fix-snapshots to master December 9, 2021 10:21

pierotibou force-pushed the pierre/missing-spans-mvc-child-actions branch from 2b0498b to 6998638 Compare December 9, 2021 12:04

This comment has been minimized.

Sign in to view

lucaspimentel removed this from the 2.0 milestone Dec 15, 2021

robertpi reviewed Dec 21, 2021

View reviewed changes

robertpi approved these changes Dec 21, 2021

View reviewed changes

tonyredondo approved these changes Dec 21, 2021

View reviewed changes

This comment has been minimized.

Sign in to view

pierotibou and others added 5 commits December 22, 2021 10:49

Add Child Action in tests to check it breaks

9bdf0c4

Handle Child actions use case

e9584e5

Having a child action would overwrite the scope stored in items. We thus failed to close all spans leading to missing spans. ResourceName needs a special handling in that case to make sure we don't overwrite the resource name with the child action one.

Apply suggestions from code review

94c729b

Co-authored-by: Andrew Lock <[email protected]>

fix trailing whitespaces from github commit

6230480

RouteTemplateResourceNamesEnabled works with child actions

59b7d25

implement comments

b29e0ed

pierotibou force-pushed the pierre/missing-spans-mvc-child-actions branch from 7ba502d to b29e0ed Compare December 22, 2021 09:58

pierotibou merged commit 3cafe9e into master Dec 22, 2021

pierotibou deleted the pierre/missing-spans-mvc-child-actions branch December 22, 2021 13:33

github-actions Bot added this to the vNext milestone Dec 22, 2021

pierotibou mentioned this pull request Dec 22, 2021

Port child actions support on v1 branch #2220

Merged

andrewlock mentioned this pull request Feb 22, 2022

[Version Bump] v1.31.2 #2486

Merged

Conversation

pierotibou commented Dec 8, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

andrewlock left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

andrewlock commented Dec 9, 2021

Benchmarks Report 🐌

Benchmark details

Raw results

Raw results

Raw results

Raw results

Faster 🎉 in #2139

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

Raw results

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!

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!

robertpi left a comment

Choose a reason for hiding this comment

Uh oh!

tonyredondo left a comment

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.

andrewlock commented Dec 22, 2021

Code Coverage Report 📊

Datadog.Trace Breakdown ✔️

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

pierotibou commented Dec 8, 2021 •

edited

Loading