diff --git a/src/OpenTelemetry.Instrumentation.AspNetCore/CHANGELOG.md b/src/OpenTelemetry.Instrumentation.AspNetCore/CHANGELOG.md index 1c18f0094f6..97681fd0553 100644 --- a/src/OpenTelemetry.Instrumentation.AspNetCore/CHANGELOG.md +++ b/src/OpenTelemetry.Instrumentation.AspNetCore/CHANGELOG.md @@ -6,6 +6,10 @@ and ActivityProcessors. Samplers, ActivityProcessor.OnStart will now get the Activity before any enrichment done by the instrumentation. ([#1836](https://github.com/open-telemetry/opentelemetry-dotnet/pull/1836)) +* Performance optimization by leveraging sampling decision and short circuiting + activity enrichment. `Filter` and `Enrich` are now only called if + `activity.IsAllDataRequested` is `true` + ([#1899](https://github.com/open-telemetry/opentelemetry-dotnet/pull/1899)) ## 1.0.0-rc2 diff --git a/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs b/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs index 911db12ce20..467f628dcbb 100644 --- a/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs +++ b/src/OpenTelemetry.Instrumentation.AspNetCore/Implementation/HttpInListener.cs @@ -57,29 +57,29 @@ public HttpInListener(string name, AspNetCoreInstrumentationOptions options) [System.Diagnostics.CodeAnalysis.SuppressMessage("Reliability", "CA2000:Dispose objects before losing scope", Justification = "The objects should not be disposed.")] public override void OnStartActivity(Activity activity, object payload) { - _ = this.startContextFetcher.TryFetch(payload, out HttpContext context); - if (context == null) + // The overall flow of what AspNetCore library does is as below: + // Activity.Start() + // DiagnosticSource.WriteEvent("Start", payload) + // DiagnosticSource.WriteEvent("Stop", payload) + // Activity.Stop() + + // This method is in the WriteEvent("Start", payload) path. + // By this time, samplers have already run and + // activity.IsAllDataRequested populated accordingly. + + if (Sdk.SuppressInstrumentation) { - AspNetCoreInstrumentationEventSource.Log.NullPayload(nameof(HttpInListener), nameof(this.OnStartActivity)); return; } - try - { - if (this.options.Filter?.Invoke(context) == false) - { - AspNetCoreInstrumentationEventSource.Log.RequestIsFilteredOut(activity.OperationName); - activity.IsAllDataRequested = false; - return; - } - } - catch (Exception ex) + _ = this.startContextFetcher.TryFetch(payload, out HttpContext context); + if (context == null) { - AspNetCoreInstrumentationEventSource.Log.RequestFilterException(ex); - activity.IsAllDataRequested = false; + AspNetCoreInstrumentationEventSource.Log.NullPayload(nameof(HttpInListener), nameof(this.OnStartActivity)); return; } + // Ensure context extraction irrespective of sampling decision var request = context.Request; var textMapPropagator = Propagators.DefaultTextMapPropagator; if (!this.hostingSupportsW3C || !(textMapPropagator is TraceContextPropagator)) @@ -110,11 +110,29 @@ public override void OnStartActivity(Activity activity, object payload) } } - ActivityInstrumentationHelper.SetActivitySourceProperty(activity, ActivitySource); - ActivityInstrumentationHelper.SetKindProperty(activity, ActivityKind.Server); - + // enrich Activity from payload only if sampling decision + // is favorable. if (activity.IsAllDataRequested) { + try + { + if (this.options.Filter?.Invoke(context) == false) + { + AspNetCoreInstrumentationEventSource.Log.RequestIsFilteredOut(activity.OperationName); + activity.IsAllDataRequested = false; + return; + } + } + catch (Exception ex) + { + AspNetCoreInstrumentationEventSource.Log.RequestFilterException(ex); + activity.IsAllDataRequested = false; + return; + } + + ActivityInstrumentationHelper.SetActivitySourceProperty(activity, ActivitySource); + ActivityInstrumentationHelper.SetKindProperty(activity, ActivityKind.Server); + var path = (request.PathBase.HasValue || request.Path.HasValue) ? (request.PathBase + request.Path).ToString() : "/"; activity.DisplayName = path; diff --git a/test/OpenTelemetry.Instrumentation.AspNetCore.Tests/BasicTests.cs b/test/OpenTelemetry.Instrumentation.AspNetCore.Tests/BasicTests.cs index 0dfe11d32ce..c34f7e7fe94 100644 --- a/test/OpenTelemetry.Instrumentation.AspNetCore.Tests/BasicTests.cs +++ b/test/OpenTelemetry.Instrumentation.AspNetCore.Tests/BasicTests.cs @@ -26,6 +26,7 @@ using Microsoft.AspNetCore.TestHost; using Microsoft.Extensions.DependencyInjection; using Moq; +using Newtonsoft.Json; using OpenTelemetry.Context.Propagation; using OpenTelemetry.Instrumentation.AspNetCore.Implementation; using OpenTelemetry.Tests; @@ -97,6 +98,8 @@ void ConfigureTestServices(IServiceCollection services) var status = activity.GetStatus(); Assert.Equal(status, Status.Unset); + + ValidateAspNetCoreActivity(activity, "/api/values"); } [Theory] @@ -190,95 +193,101 @@ public async Task SuccessfulTemplateControllerCallUsesParentContext() // is always ignored and new one is created by the Instrumentation Assert.Equal("ActivityCreatedByHttpInListener", activity.OperationName); #endif - Assert.Equal(ActivityKind.Server, activity.Kind); Assert.Equal("api/Values/{id}", activity.DisplayName); - Assert.Equal("/api/values/2", activity.GetTagValue(SpanAttributeConstants.HttpPathKey) as string); Assert.Equal(expectedTraceId, activity.Context.TraceId); Assert.Equal(expectedSpanId, activity.ParentSpanId); + + ValidateAspNetCoreActivity(activity, "/api/values/2"); } [Fact] public async Task CustomPropagator() { - var activityProcessor = new Mock>(); - - var expectedTraceId = ActivityTraceId.CreateRandom(); - var expectedSpanId = ActivitySpanId.CreateRandom(); - - var propagator = new Mock(); - propagator.Setup(m => m.Extract(It.IsAny(), It.IsAny(), It.IsAny>>())).Returns( - new PropagationContext( - new ActivityContext( - expectedTraceId, - expectedSpanId, - ActivityTraceFlags.Recorded), - default)); - - // Arrange - using (var testFactory = this.factory - .WithWebHostBuilder(builder => - builder.ConfigureTestServices(services => - { - Sdk.SetDefaultTextMapPropagator(propagator.Object); - this.openTelemetrySdk = Sdk.CreateTracerProviderBuilder() - .AddAspNetCoreInstrumentation() - .AddProcessor(activityProcessor.Object) - .Build(); - }))) + try { - using var client = testFactory.CreateClient(); - var response = await client.GetAsync("/api/values/2"); - response.EnsureSuccessStatusCode(); // Status Code 200-299 + var activityProcessor = new Mock>(); + + var expectedTraceId = ActivityTraceId.CreateRandom(); + var expectedSpanId = ActivitySpanId.CreateRandom(); + + var propagator = new Mock(); + propagator.Setup(m => m.Extract(It.IsAny(), It.IsAny(), It.IsAny>>())).Returns( + new PropagationContext( + new ActivityContext( + expectedTraceId, + expectedSpanId, + ActivityTraceFlags.Recorded), + default)); + + // Arrange + using (var testFactory = this.factory + .WithWebHostBuilder(builder => + builder.ConfigureTestServices(services => + { + Sdk.SetDefaultTextMapPropagator(propagator.Object); + this.openTelemetrySdk = Sdk.CreateTracerProviderBuilder() + .AddAspNetCoreInstrumentation() + .AddProcessor(activityProcessor.Object) + .Build(); + }))) + { + using var client = testFactory.CreateClient(); + var response = await client.GetAsync("/api/values/2"); + response.EnsureSuccessStatusCode(); // Status Code 200-299 - WaitForProcessorInvocations(activityProcessor, 4); - } + WaitForProcessorInvocations(activityProcessor, 4); + } - // List of invocations on the processor - // 1. SetParentProvider for TracerProviderSdk - // 2. OnStart for the activity created by AspNetCore with the OperationName: Microsoft.AspNetCore.Hosting.HttpRequestIn - // 3. OnStart for the sibling activity created by the instrumentation library with the OperationName: ActivityCreatedByHttpInListener - // 4. OnEnd for the sibling activity created by the instrumentation library with the OperationName: ActivityCreatedByHttpInListener - Assert.Equal(4, activityProcessor.Invocations.Count); + // List of invocations on the processor + // 1. SetParentProvider for TracerProviderSdk + // 2. OnStart for the activity created by AspNetCore with the OperationName: Microsoft.AspNetCore.Hosting.HttpRequestIn + // 3. OnStart for the sibling activity created by the instrumentation library with the OperationName: ActivityCreatedByHttpInListener + // 4. OnEnd for the sibling activity created by the instrumentation library with the OperationName: ActivityCreatedByHttpInListener + Assert.Equal(4, activityProcessor.Invocations.Count); - var startedActivities = activityProcessor.Invocations.Where(invo => invo.Method.Name == "OnStart"); - var stoppedActivities = activityProcessor.Invocations.Where(invo => invo.Method.Name == "OnEnd"); - Assert.Equal(2, startedActivities.Count()); - Assert.Single(stoppedActivities); + var startedActivities = activityProcessor.Invocations.Where(invo => invo.Method.Name == "OnStart"); + var stoppedActivities = activityProcessor.Invocations.Where(invo => invo.Method.Name == "OnEnd"); + Assert.Equal(2, startedActivities.Count()); + Assert.Single(stoppedActivities); - // The activity created by the framework and the sibling activity are both sent to Processor.OnStart - Assert.Contains(startedActivities, item => - { - var startedActivity = item.Arguments[0] as Activity; - return startedActivity.OperationName == HttpInListener.ActivityOperationName; - }); + // The activity created by the framework and the sibling activity are both sent to Processor.OnStart + Assert.Contains(startedActivities, item => + { + var startedActivity = item.Arguments[0] as Activity; + return startedActivity.OperationName == HttpInListener.ActivityOperationName; + }); - Assert.Contains(startedActivities, item => - { - var startedActivity = item.Arguments[0] as Activity; - return startedActivity.OperationName == HttpInListener.ActivityNameByHttpInListener; - }); + Assert.Contains(startedActivities, item => + { + var startedActivity = item.Arguments[0] as Activity; + return startedActivity.OperationName == HttpInListener.ActivityNameByHttpInListener; + }); - // Only the sibling activity is sent to Processor.OnEnd - Assert.Contains(stoppedActivities, item => - { - var stoppedActivity = item.Arguments[0] as Activity; - return stoppedActivity.OperationName == HttpInListener.ActivityNameByHttpInListener; - }); + // Only the sibling activity is sent to Processor.OnEnd + Assert.Contains(stoppedActivities, item => + { + var stoppedActivity = item.Arguments[0] as Activity; + return stoppedActivity.OperationName == HttpInListener.ActivityNameByHttpInListener; + }); - var activity = activityProcessor.Invocations.FirstOrDefault(invo => invo.Method.Name == "OnEnd").Arguments[0] as Activity; - Assert.Equal(ActivityKind.Server, activity.Kind); - Assert.True(activity.Duration != TimeSpan.Zero); - Assert.Equal("api/Values/{id}", activity.DisplayName); - Assert.Equal("/api/values/2", activity.GetTagValue(SpanAttributeConstants.HttpPathKey) as string); + var activity = activityProcessor.Invocations.FirstOrDefault(invo => invo.Method.Name == "OnEnd").Arguments[0] as Activity; + Assert.True(activity.Duration != TimeSpan.Zero); + Assert.Equal("api/Values/{id}", activity.DisplayName); - Assert.Equal(expectedTraceId, activity.Context.TraceId); - Assert.Equal(expectedSpanId, activity.ParentSpanId); - Sdk.SetDefaultTextMapPropagator(new CompositeTextMapPropagator(new TextMapPropagator[] + Assert.Equal(expectedTraceId, activity.Context.TraceId); + Assert.Equal(expectedSpanId, activity.ParentSpanId); + + ValidateAspNetCoreActivity(activity, "/api/values/2"); + } + finally { - new TraceContextPropagator(), - new BaggagePropagator(), - })); + Sdk.SetDefaultTextMapPropagator(new CompositeTextMapPropagator(new TextMapPropagator[] + { + new TraceContextPropagator(), + new BaggagePropagator(), + })); + } } [Fact] @@ -322,8 +331,7 @@ void ConfigureTestServices(IServiceCollection services) Assert.Single(activityProcessor.Invocations, invo => invo.Method.Name == "OnEnd"); var activity = activityProcessor.Invocations.FirstOrDefault(invo => invo.Method.Name == "OnEnd").Arguments[0] as Activity; - Assert.Equal(ActivityKind.Server, activity.Kind); - Assert.Equal("/api/values", activity.GetTagValue(SpanAttributeConstants.HttpPathKey) as string); + ValidateAspNetCoreActivity(activity, "/api/values"); } [Fact] @@ -383,8 +391,109 @@ void ConfigureTestServices(IServiceCollection services) Assert.Single(activityProcessor.Invocations, invo => invo.Method.Name == "OnEnd"); var activity = activityProcessor.Invocations.FirstOrDefault(invo => invo.Method.Name == "OnEnd").Arguments[0] as Activity; - Assert.Equal(ActivityKind.Server, activity.Kind); - Assert.Equal("/api/values", activity.GetTagValue(SpanAttributeConstants.HttpPathKey) as string); + ValidateAspNetCoreActivity(activity, "/api/values"); + } + + [Theory] + [InlineData(SamplingDecision.Drop)] + [InlineData(SamplingDecision.RecordOnly)] + [InlineData(SamplingDecision.RecordAndSample)] + public async Task ExtractContextIrrespectiveOfSamplingDecision(SamplingDecision samplingDecision) + { + try + { + var expectedTraceId = ActivityTraceId.CreateRandom(); + var expectedParentSpanId = ActivitySpanId.CreateRandom(); + var expectedTraceState = "rojo=1,congo=2"; + var activityContext = new ActivityContext(expectedTraceId, expectedParentSpanId, ActivityTraceFlags.Recorded, expectedTraceState); + var expectedBaggage = Baggage.SetBaggage("key1", "value1").SetBaggage("key2", "value2"); + Sdk.SetDefaultTextMapPropagator(new ExtractOnlyPropagator(activityContext, expectedBaggage)); + + // Arrange + using (var testFactory = this.factory + .WithWebHostBuilder(builder => + builder.ConfigureTestServices(services => + { + this.openTelemetrySdk = Sdk.CreateTracerProviderBuilder() + .SetSampler(new TestSampler(samplingDecision)) + .AddAspNetCoreInstrumentation() + .Build(); + }))) + { + using var client = testFactory.CreateClient(); + + // Test TraceContext Propagation + var request = new HttpRequestMessage(HttpMethod.Get, "/api/GetChildActivityTraceContext"); + var response = await client.SendAsync(request); + var childActivityTraceContext = JsonConvert.DeserializeObject>(response.Content.ReadAsStringAsync().Result); + + response.EnsureSuccessStatusCode(); + + Assert.Equal(expectedTraceId.ToString(), childActivityTraceContext["TraceId"]); + Assert.Equal(expectedTraceState, childActivityTraceContext["TraceState"]); + Assert.NotEqual(expectedParentSpanId.ToString(), childActivityTraceContext["ParentSpanId"]); // there is a new activity created in instrumentation therefore the ParentSpanId is different that what is provided in the headers + + // Test Baggage Context Propagation + request = new HttpRequestMessage(HttpMethod.Get, "/api/GetChildActivityBaggageContext"); + + response = await client.SendAsync(request); + var childActivityBaggageContext = JsonConvert.DeserializeObject>(response.Content.ReadAsStringAsync().Result); + + response.EnsureSuccessStatusCode(); + + Assert.Single(childActivityBaggageContext, item => item.Key == "key1" && item.Value == "value1"); + Assert.Single(childActivityBaggageContext, item => item.Key == "key2" && item.Value == "value2"); + } + } + finally + { + Sdk.SetDefaultTextMapPropagator(new CompositeTextMapPropagator(new TextMapPropagator[] + { + new TraceContextPropagator(), + new BaggagePropagator(), + })); + } + } + + [Theory] + [InlineData(SamplingDecision.Drop, false, false)] + [InlineData(SamplingDecision.RecordOnly, true, true)] + [InlineData(SamplingDecision.RecordAndSample, true, true)] + public async Task FilterAndEnrichAreOnlyCalledWhenSampled(SamplingDecision samplingDecision, bool shouldFilterBeCalled, bool shouldEnrichBeCalled) + { + bool filterCalled = false; + bool enrichCalled = false; + void ConfigureTestServices(IServiceCollection services) + { + this.openTelemetrySdk = Sdk.CreateTracerProviderBuilder() + .SetSampler(new TestSampler(samplingDecision)) + .AddAspNetCoreInstrumentation(options => + { + options.Filter = (context) => + { + filterCalled = true; + return true; + }; + options.Enrich = (activity, methodName, request) => + { + enrichCalled = true; + }; + }) + .Build(); + } + + // Arrange + using var client = this.factory + .WithWebHostBuilder(builder => + builder.ConfigureTestServices(ConfigureTestServices)) + .CreateClient(); + + // Act + var response = await client.GetAsync("/api/values"); + + // Assert + Assert.Equal(shouldFilterBeCalled, filterCalled); + Assert.Equal(shouldEnrichBeCalled, enrichCalled); } public void Dispose() @@ -409,6 +518,8 @@ private static void WaitForProcessorInvocations(Mock> ac private static void ValidateAspNetCoreActivity(Activity activityToValidate, string expectedHttpPath) { Assert.Equal(ActivityKind.Server, activityToValidate.Kind); + Assert.Equal(HttpInListener.ActivitySourceName, activityToValidate.Source.Name); + Assert.Equal(HttpInListener.Version.ToString(), activityToValidate.Source.Version); Assert.Equal(expectedHttpPath, activityToValidate.GetTagValue(SpanAttributeConstants.HttpPathKey) as string); } @@ -429,5 +540,44 @@ private static void ActivityEnrichment(Activity activity, string method, object break; } } + + private class ExtractOnlyPropagator : TextMapPropagator + { + private readonly ActivityContext activityContext; + private readonly Baggage baggage; + + public ExtractOnlyPropagator(ActivityContext activityContext, Baggage baggage) + { + this.activityContext = activityContext; + this.baggage = baggage; + } + + public override ISet Fields => throw new NotImplementedException(); + + public override PropagationContext Extract(PropagationContext context, T carrier, Func> getter) + { + return new PropagationContext(this.activityContext, this.baggage); + } + + public override void Inject(PropagationContext context, T carrier, Action setter) + { + throw new NotImplementedException(); + } + } + + private class TestSampler : Sampler + { + private SamplingDecision samplingDecision; + + public TestSampler(SamplingDecision samplingDecision) + { + this.samplingDecision = samplingDecision; + } + + public override SamplingResult ShouldSample(in SamplingParameters samplingParameters) + { + return new SamplingResult(this.samplingDecision); + } + } } } diff --git a/test/TestApp.AspNetCore.2.1/Controllers/ChildActivityController.cs b/test/TestApp.AspNetCore.2.1/Controllers/ChildActivityController.cs new file mode 100644 index 00000000000..dab0b28f667 --- /dev/null +++ b/test/TestApp.AspNetCore.2.1/Controllers/ChildActivityController.cs @@ -0,0 +1,46 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// + +using System.Collections.Generic; +using System.Diagnostics; +using Microsoft.AspNetCore.Mvc; +using OpenTelemetry; + +namespace TestApp.AspNetCore._2._1.Controllers +{ + public class ChildActivityController : Controller + { + [Route("api/GetChildActivityTraceContext")] + public Dictionary GetChildActivityTraceContext() + { + var result = new Dictionary(); + var activity = new Activity("ActivityInsideHttpRequest"); + activity.Start(); + result["TraceId"] = activity.Context.TraceId.ToString(); + result["ParentSpanId"] = activity.ParentSpanId.ToString(); + result["TraceState"] = activity.Context.TraceState; + activity.Stop(); + return result; + } + + [Route("api/GetChildActivityBaggageContext")] + public IReadOnlyDictionary GetChildActivityBaggageContext() + { + var result = Baggage.Current.GetBaggage(); + return result; + } + } +} diff --git a/test/TestApp.AspNetCore.3.1/Controllers/ChildActivityController.cs b/test/TestApp.AspNetCore.3.1/Controllers/ChildActivityController.cs new file mode 100644 index 00000000000..911f9bae6a3 --- /dev/null +++ b/test/TestApp.AspNetCore.3.1/Controllers/ChildActivityController.cs @@ -0,0 +1,46 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// + +using System.Collections.Generic; +using System.Diagnostics; +using Microsoft.AspNetCore.Mvc; +using OpenTelemetry; + +namespace TestApp.AspNetCore._3._1.Controllers +{ + public class ChildActivityController : Controller + { + [Route("api/GetChildActivityTraceContext")] + public Dictionary GetChildActivityTraceContext() + { + var result = new Dictionary(); + var activity = new Activity("ActivityInsideHttpRequest"); + activity.Start(); + result["TraceId"] = activity.Context.TraceId.ToString(); + result["ParentSpanId"] = activity.ParentSpanId.ToString(); + result["TraceState"] = activity.Context.TraceState; + activity.Stop(); + return result; + } + + [Route("api/GetChildActivityBaggageContext")] + public IReadOnlyDictionary GetChildActivityBaggageContext() + { + var result = Baggage.Current.GetBaggage(); + return result; + } + } +} diff --git a/test/TestApp.AspNetCore.5.0/Controllers/ChildActivityController.cs b/test/TestApp.AspNetCore.5.0/Controllers/ChildActivityController.cs new file mode 100644 index 00000000000..39c556d775c --- /dev/null +++ b/test/TestApp.AspNetCore.5.0/Controllers/ChildActivityController.cs @@ -0,0 +1,46 @@ +// +// Copyright The OpenTelemetry Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// + +using System.Collections.Generic; +using System.Diagnostics; +using Microsoft.AspNetCore.Mvc; +using OpenTelemetry; + +namespace TestApp.AspNetCore._5._0.Controllers +{ + public class ChildActivityController : Controller + { + [Route("api/GetChildActivityTraceContext")] + public Dictionary GetChildActivityTraceContext() + { + var result = new Dictionary(); + var activity = new Activity("ActivityInsideHttpRequest"); + activity.Start(); + result["TraceId"] = activity.Context.TraceId.ToString(); + result["ParentSpanId"] = activity.ParentSpanId.ToString(); + result["TraceState"] = activity.Context.TraceState; + activity.Stop(); + return result; + } + + [Route("api/GetChildActivityBaggageContext")] + public IReadOnlyDictionary GetChildActivityBaggageContext() + { + var result = Baggage.Current.GetBaggage(); + return result; + } + } +}