Should this turn out to be useful for anyone, I'll gladly turn it into a community wiki thing.
I have some slow pages in an MVC3 app, and since little of the execution time seemed to happen in my code, I wanted to see if I could find out more about what took so long. Not that I succeeded, but I gained a little more wisdom along the way.
There is nothing here that isn't obvious to anyone with some MVC experience. Basically, I created my own ActionFilterAttribute that looks like this:
public class ProfilerAttribute : ActionFilterAttribute
{
IDisposable actionStep = null;
IDisposable resultStep = null;
public override void OnActionExecuting(ActionExecutingContext filterContext)
{
actionStep = MiniProfiler.Current.Step("OnActionExecuting " + ResultDescriptor(filterContext));
base.OnActionExecuting(filterContext);
}
public override void OnActionExecuted(ActionExecutedContext filterContext)
{
if (actionStep != null)
{
actionStep.Dispose();
actionStep = null;
}
base.OnActionExecuted(filterContext);
}
public override void OnResultExecuting(ResultExecutingContext filterContext)
{
resultStep = MiniProfiler.Current.Step("OnResultExecuting " + ResultDescriptor(filterContext));
base.OnResultExecuting(filterContext);
}
public override void OnResultExecuted(ResultExecutedContext filterContext)
{
if (resultStep != null)
{
resultStep.Dispose();
resultStep = null;
}
base.OnResultExecuted(filterContext);
}
private string ResultDescriptor(ActionExecutingContext filterContext)
{
return filterContext.ActionDescriptor.ControllerDescriptor.ControllerName + "." + filterContext.ActionDescriptor.ActionName;
}
private string ResultDescriptor(ResultExecutingContext filterContext)
{
var values = filterContext.RouteData.Values;
return String.Format("{0}.{1}", values["controller"], values["action"]);
}
This seems to work well, and in my case I have learned that most of the time is actually spent in the ResultExecuting part of life, not inside my actions.
However, I have some questions about this approach.
1) Is this a request-safe way of doing things? I am guessing no, since the actionfilter is created only once, in the RegisterGlobalFilters() method in Global.asax.cs. If two requests appear at once, actionStep and resultStep will be worthless. Is this true? If so, can someone who knows more than me contribute a clever way to handle this? Works for me during local machine profiling, but probably not so much deployed on a server with multiple people making requests at the same time.
2) Is there any way to get more insight into the result-executing process? Or should I just accept that rendering the view etc. takes the time it takes? In my own app I ensure that all database access is finished before my action method is over (using NHibernate Profiler in my case), and I like to keep my views slim and simple; Any kind of insight into what slows the rendering down could still be useful, though. I guess using the Mini Profiler in my model objects would show up here, if any slow code on my part was executed here.
3) The ResultDescriptor methods are probably evil and poisonous. They've worked for me in my tests, but would probably need to be replaced by something more robust. I just went with the first versions that gave me something halfway useful.
Any other comments to this would also be very welcome, even if they are "This is a bad idea, go die alone".