Skip to content

Commit

Permalink
Optimize MVC diagnostic listener (#584)
Browse files Browse the repository at this point in the history 
Meant to do this a while ago - stop generating strings for repeated things. We have a finite amount of combinations here, so let's use that to our advantage.

Overall, we most often have a pair of one label that doesn't change at all and a second string within a finite set. Because of this, we can cache the tuple or 2 => string conversion and not allocate to gen 0 per step. Since the conversion of source => final string on the second half only happens once, we can also prettify it a bit without paying the cost each time.
  • Loading branch information
@NickCraver
NickCraver committed Nov 7, 2021
1 parent a461068 commit a48fc7a
Showing 1 changed file with 80 additions and 55 deletions.
135 changes: 80 additions & 55 deletions src/MiniProfiler.AspNetCore.Mvc/MvcDiagnosticListener.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
using Microsoft.AspNetCore.Mvc.Abstractions;
using Microsoft.AspNetCore.Mvc.Diagnostics;
using Microsoft.AspNetCore.Mvc.Filters;
using Microsoft.AspNetCore.Mvc.RazorPages.Infrastructure;
using StackExchange.Profiling.Internal;
using System;
using System.Collections.Concurrent;
Expand Down Expand Up @@ -31,7 +32,10 @@ public class MvcDiagnosticListener : IMiniProfilerDiagnosticListener
/// <summary>
/// Notifies the observer that the provider has finished sending push-based notifications.
/// </summary>
public void OnCompleted() { }
public void OnCompleted()
{
_descriptorNameCache.Clear();
}

/// <summary>
/// Notifies the observer that the provider has experienced an error condition.
Expand All @@ -40,41 +44,24 @@ public class MvcDiagnosticListener : IMiniProfilerDiagnosticListener
public void OnError(Exception error) => Trace.WriteLine(error);

// So we don't keep allocating strings for the same actions over and over
private readonly ConcurrentDictionary<(string, string), string> _descriptorNameCache = new ConcurrentDictionary<(string, string), string>();
private readonly ConcurrentDictionary<(string, string), string> _descriptorNameCache = new();
private const string _labelSeparator = ": ";

private string GetName(string label, ActionDescriptor descriptor)
/// <summary>
/// Gets a cached concatenation since this is such a hot path - don't keep allocating.
/// </summary>
private string GetName(string label, string name, Func<string, string> trim = null)
{
var key = (label, descriptor.DisplayName);
var key = (label, name);
if (!_descriptorNameCache.TryGetValue(key, out var result))
{
// For the "Samples.AspNetCore.Controllers.HomeController.Index (Samples.AspNetCore3)" format,
// ...trim off the assembly on the end.
var assemblyNamePos = descriptor.DisplayName.IndexOf(" (");
if (assemblyNamePos > 0)
{
result = string.Concat(label, ": ", descriptor.DisplayName.AsSpan().Slice(0, assemblyNamePos));
}
else
{
result = label + ": " + descriptor.DisplayName;
}
name = trim?.Invoke(name) ?? name;
result = label + _labelSeparator + name;
_descriptorNameCache[key] = result;
}
return result;
}

private static string GetName(IActionResult result) => result switch
{
ViewResult vr => vr.ViewName.HasValue() ? "View: " + vr.ViewName : nameof(ViewResult),
ContentResult cr => cr.ContentType.HasValue() ? "Content: " + cr.ContentType : nameof(ContentResult),
ObjectResult or => or.DeclaredType != null ? "Object: " + or.DeclaredType.Name : nameof(ObjectResult),
StatusCodeResult scr => scr.StatusCode > 0 ? "Status Code: " + scr.StatusCode.ToString() : nameof(StatusCodeResult),
JsonResult jr => jr.ContentType.HasValue() ? "JSON: " + jr.ContentType : nameof(JsonResult),
_ => "Result: " + result.GetType().Name
};

private static string GetName(IFilterMetadata filter) => filter.GetType().Name;

private class StackTiming
{
public object State { get; set; }
Expand All @@ -88,31 +75,69 @@ private class StackTiming
/// <summary>
/// Stores the current timing in the tree, on each request.
/// </summary>
private readonly AsyncLocal<StackTiming> CurrentTiming = new AsyncLocal<StackTiming>();
private readonly AsyncLocal<StackTiming> CurrentTiming = new();

private object StartAction<T>(string label, T descriptor) where T : ActionDescriptor
{
var profiler = MiniProfiler.Current;
var stepName = GetName(label, descriptor.DisplayName, name =>
{
// For the "Samples.AspNetCore.Controllers.HomeController.Index (Samples.AspNetCore3)" format,
// ...trim off the assembly on the end.
var assemblyNamePos = name.IndexOf(" (");
return assemblyNamePos > 0
? descriptor.DisplayName[..assemblyNamePos]
: descriptor.DisplayName;
});

CurrentTiming.Value = new StackTiming(descriptor, profiler != null ? new Timing(profiler, profiler.Head, stepName, null, null, debugStackShave: 4) : null, CurrentTiming.Value);
return null;
}

private object StartActionResult<T>(T result) where T : IActionResult
{
var profiler = MiniProfiler.Current;
var stepName = result switch
{
ViewResult vr => vr.ViewName.HasValue() ? GetName("View", vr.ViewName) : nameof(ViewResult),
ContentResult cr => cr.ContentType.HasValue() ? GetName("Content", cr.ContentType) : nameof(ContentResult),
ObjectResult or => or.DeclaredType != null ? GetName("Object", or.DeclaredType.Name) : nameof(ObjectResult),
StatusCodeResult scr => scr.StatusCode > 0 ? GetName("Status Code", scr.StatusCode.ToString()) : nameof(StatusCodeResult),
JsonResult jr => jr.ContentType.HasValue() ? GetName("JSON", jr.ContentType) : nameof(JsonResult),
_ => GetName("Result", result.GetType().Name)
};

CurrentTiming.Value = new StackTiming(result, profiler != null ? new Timing(profiler, profiler.Head, stepName, null, null, debugStackShave: 4) : null, CurrentTiming.Value);
return null;
}

private object StartFilter<T>(T state, string stepName) where T : class
private object StartFilter<T>(string label, T filter) where T : IFilterMetadata
{
var profiler = MiniProfiler.Current;
if (profiler?.Options is MiniProfilerOptions opts && opts.EnableMvcFilterProfiling)
{
CurrentTiming.Value = new StackTiming(state, new Timing(profiler, profiler.Head, stepName, opts.MvcFilterMinimumSaveMs, true, debugStackShave: 4), CurrentTiming.Value);
var stepName = GetName(label, filter.GetType().Name, name => name.EndsWith("Attribute") ? name[..^"Attribute".Length] : name);
CurrentTiming.Value = new StackTiming(filter, new Timing(profiler, profiler.Head, stepName, opts.MvcFilterMinimumSaveMs, true, debugStackShave: 4), CurrentTiming.Value);
}
return null;
}

private object StartView<T>(T state, string stepName) where T : class
private object StartView<T>(T state, string label, string viewName) where T : class
{
var profiler = MiniProfiler.Current;
if (profiler?.Options is MiniProfilerOptions opts && opts.EnableMvcViewProfiling)
{
// Trim /Views/ to / for brevity
var stepName = GetName(label, viewName, name => name?.StartsWith("/Views/") == true ? name["/Views/".Length..] : name);
CurrentTiming.Value = new StackTiming(state, new Timing(profiler, profiler.Head, stepName, opts.MvcViewMinimumSaveMs, true, debugStackShave: 4), CurrentTiming.Value);
}
return null;
}

private object Start<T>(T state, string stepName) where T : class
private object StartHandler<T>(T state, HandlerMethodDescriptor handler) where T : class
{
var profiler = MiniProfiler.Current;
var stepName = GetName("Handler", handler.Name);
CurrentTiming.Value = new StackTiming(state, profiler != null ? new Timing(profiler, profiler.Head, stepName, null, null, debugStackShave: 4) : null, CurrentTiming.Value);
return null;
}
Expand Down Expand Up @@ -144,86 +169,86 @@ public void OnNext(KeyValuePair<string, object> kv)
{
// MVC Bits: https://github.com/dotnet/aspnetcore/blob/v3.0.0/src/Mvc/Mvc.Core/src/Diagnostics/MvcDiagnostics.cs
// ActionEvent
BeforeActionEventData data => Start(data.ActionDescriptor, GetName("Action", data.ActionDescriptor)),
BeforeActionEventData data => StartAction("Action", data.ActionDescriptor),
AfterActionEventData data => Complete(data.ActionDescriptor),
// ControllerActionMethod
BeforeControllerActionMethodEventData data => Start(data.ActionContext.ActionDescriptor, GetName("Controller Action", data.ActionContext.ActionDescriptor)),
BeforeControllerActionMethodEventData data => StartAction("Controller Action", data.ActionContext.ActionDescriptor),
AfterControllerActionMethodEventData data => Complete(data.ActionContext.ActionDescriptor),
// ActionResultEvent
BeforeActionResultEventData data => Start(data.Result, GetName(data.Result)),
BeforeActionResultEventData data => StartActionResult(data.Result),
AfterActionResultEventData data => Complete(data.Result),

// AuthorizationFilterOnAuthorization
BeforeAuthorizationFilterOnAuthorizationEventData data => StartFilter(data.Filter, "Auth Filter: " + GetName(data.Filter)),
BeforeAuthorizationFilterOnAuthorizationEventData data => StartFilter("Auth Filter", data.Filter),
AfterAuthorizationFilterOnAuthorizationEventData data => Complete(data.Filter),

// ResourceFilterOnResourceExecution
BeforeResourceFilterOnResourceExecutionEventData data => StartFilter(data.Filter, "Resource Filter (Exec): " + GetName(data.Filter)),
BeforeResourceFilterOnResourceExecutionEventData data => StartFilter("Resource Filter (Exec)", data.Filter),
AfterResourceFilterOnResourceExecutionEventData data => Complete(data.Filter),
// ResourceFilterOnResourceExecuting
BeforeResourceFilterOnResourceExecutingEventData data => StartFilter(data.Filter, "Resource Filter (Execing): " + GetName(data.Filter)),
BeforeResourceFilterOnResourceExecutingEventData data => StartFilter("Resource Filter (Execing)", data.Filter),
AfterResourceFilterOnResourceExecutingEventData data => Complete(data.Filter),
// ResourceFilterOnResourceExecuted
BeforeResourceFilterOnResourceExecutedEventData data => StartFilter(data.Filter, "Resource Filter (Execed): " + GetName(data.Filter)),
BeforeResourceFilterOnResourceExecutedEventData data => StartFilter("Resource Filter (Execed)", data.Filter),
AfterResourceFilterOnResourceExecutedEventData data => Complete(data.Filter),

// ExceptionFilterOnException
BeforeExceptionFilterOnException data => StartFilter(data.Filter, "Exception Filter: " + GetName(data.Filter)),
BeforeExceptionFilterOnException data => StartFilter("Exception Filter", data.Filter),
AfterExceptionFilterOnExceptionEventData data => Complete(data.Filter),

// ActionFilterOnActionExecution
BeforeActionFilterOnActionExecutionEventData data => StartFilter(data.Filter, "Action Filter (Exec): " + GetName(data.Filter)),
BeforeActionFilterOnActionExecutionEventData data => StartFilter("Action Filter (Exec)", data.Filter),
AfterActionFilterOnActionExecutionEventData data => Complete(data.Filter),
// ActionFilterOnActionExecuting
BeforeActionFilterOnActionExecutingEventData data => StartFilter(data.Filter, "Action Filter (Execing): " + GetName(data.Filter)),
BeforeActionFilterOnActionExecutingEventData data => StartFilter("Action Filter (Execing)", data.Filter),
AfterActionFilterOnActionExecutingEventData data => Complete(data.Filter),
// ActionFilterOnActionExecuted
BeforeActionFilterOnActionExecutedEventData data => StartFilter(data.Filter, "Action Filter (Execed): " + GetName(data.Filter)),
BeforeActionFilterOnActionExecutedEventData data => StartFilter("Action Filter (Execed)", data.Filter),
AfterActionFilterOnActionExecutedEventData data => Complete(data.Filter),

// ResultFilterOnResultExecution
BeforeResultFilterOnResultExecutionEventData data => StartFilter(data.Filter, "Result Filter (Exec): " + GetName(data.Filter)),
BeforeResultFilterOnResultExecutionEventData data => StartFilter("Result Filter (Exec)", data.Filter),
AfterResultFilterOnResultExecutionEventData data => Complete(data.Filter),
// ResultFilterOnResultExecuting
BeforeResultFilterOnResultExecutingEventData data => StartFilter(data.Filter, "Result Filter (Execing): " + GetName(data.Filter)),
BeforeResultFilterOnResultExecutingEventData data => StartFilter("Result Filter (Execing)", data.Filter),
AfterResultFilterOnResultExecutingEventData data => Complete(data.Filter),
// ResultFilterOnResultExecuted
BeforeResultFilterOnResultExecutedEventData data => StartFilter(data.Filter, "Result Filter (Execed): " + GetName(data.Filter)),
BeforeResultFilterOnResultExecutedEventData data => StartFilter("Result Filter (Execed)", data.Filter),
AfterResultFilterOnResultExecutedEventData data => Complete(data.Filter),

// Razor Bits: https://github.com/dotnet/aspnetcore/blob/v3.0.0/src/Mvc/Mvc.Razor/src/Diagnostics/MvcDiagnostics.cs
// ViewPage
BeforeViewPageEventData data => StartView(data.Page, "View: " + data.Page.Path),
BeforeViewPageEventData data => StartView(data.Page, "View", data.Page.Path),
AfterViewPageEventData data => Complete(data.Page),

// ViewComponent
BeforeViewComponentEventData data => StartView(data.ViewComponentContext, "Component (Invoke): " + data.ViewComponentContext.ViewComponentDescriptor.ShortName),
BeforeViewComponentEventData data => StartView(data.ViewComponentContext, "Component (Invoke)", data.ViewComponentContext.ViewComponentDescriptor.ShortName),
AfterViewComponentEventData data => Complete(data.ViewComponentContext),

// Intentionally not registering to slim view wrapper due to noise, accounted for in View: above.
//ViewComponentBeforeViewExecuteEventData data => StartView(data.ViewComponentContext, "Component (View): " + data.ViewComponentContext.ViewComponentDescriptor.ShortName),
//ViewComponentBeforeViewExecuteEventData data => StartView(data.ViewComponentContext, "Component (View)", data.ViewComponentContext.ViewComponentDescriptor.ShortName),
//ViewComponentAfterViewExecuteEventData data => Complete(data.ViewComponentContext),

// RazorPage Bits: https://github.com/dotnet/aspnetcore/blob/v3.0.0/src/Mvc/Mvc.RazorPages/src/Diagnostics/MvcDiagnostics.cs
// HandlerMethod
BeforeHandlerMethodEventData data => Start(data.Instance, "Handler: " + data.HandlerMethodDescriptor.Name),
BeforeHandlerMethodEventData data => StartHandler(data.Instance, data.HandlerMethodDescriptor),
AfterHandlerMethodEventData data => Complete(data.Instance),

// PageFilterOnPageHandlerExecution
BeforePageFilterOnPageHandlerExecutionEventData data => StartFilter(data.Filter, "Filter (Exec): " + GetName(data.Filter)),
BeforePageFilterOnPageHandlerExecutionEventData data => StartFilter("Filter (Exec)", data.Filter),
AfterPageFilterOnPageHandlerExecutionEventData data => Complete(data.Filter),
// PageFilterOnPageHandlerExecuting
BeforePageFilterOnPageHandlerExecutingEventData data => StartFilter(data.Filter, "Filter (Execing): " + GetName(data.Filter)),
BeforePageFilterOnPageHandlerExecutingEventData data => StartFilter("Filter (Execing)", data.Filter),
AfterPageFilterOnPageHandlerExecutingEventData data => Complete(data.Filter),
// PageFilterOnPageHandlerExecuted
BeforePageFilterOnPageHandlerExecutedEventData data => StartFilter(data.Filter, "Filter (Execed): " + GetName(data.Filter)),
BeforePageFilterOnPageHandlerExecutedEventData data => StartFilter("Filter (Execed)", data.Filter),
AfterPageFilterOnPageHandlerExecutedEventData data => Complete(data.Filter),

// PageFilterOnPageHandlerSelection
BeforePageFilterOnPageHandlerSelectionEventData data => StartFilter(data.Filter, "Filter (Selection): " + GetName(data.Filter)),
BeforePageFilterOnPageHandlerSelectionEventData data => StartFilter("Filter (Selection)", data.Filter),
AfterPageFilterOnPageHandlerSelectionEventData data => Complete(data.Filter),
// PageFilterOnPageHandlerSelected
BeforePageFilterOnPageHandlerSelectedEventData data => StartFilter(data.Filter, "Filter (Selected): " + GetName(data.Filter)),
BeforePageFilterOnPageHandlerSelectedEventData data => StartFilter("Filter (Selected)", data.Filter),
AfterPageFilterOnPageHandlerSelectedEventData data => Complete(data.Filter),
_ => null
};
Expand Down

0 comments on commit a48fc7a

Please sign in to comment.