Measure Time Invoking ASP.NET MVC Controller Actions

Question

Some users of an MVC 4 app are experiencing sporadic slowness. Presumably not every user reports that problem every time it happens to them.

My thought is to measure the time spent in each controller action and log details of action invocations that exceed a prescribed time to facilitate further analysis (to rule in or rule out a server/code issue).

Is there a convenient way to hook in to perform such measurements so that I can avoid adding instrumentation code to each action? I'm not currently using IOC for this project and would hesitate to introduce it just to solve this issue.

Is there a better way to tackle this type of problem?

Solution 1

Could you create a global action filter? Something like this:

public class PerformanceTestFilter : IActionFilter
{
    private Stopwatch stopWatch = new Stopwatch();

    public void OnActionExecuting(ActionExecutingContext filterContext)
    {
        stopWatch.Reset();
        stopWatch.Start();
    }

    public void OnActionExecuted(ActionExecutedContext filterContext)
    {
        stopWatch.Stop();
        var executionTime = stopWatch.ElapsedMilliseconds;
        // Do something with the executionTime
    }
}

and then add it to your GlobalFilters collection in `Application_Start()'

GlobalFilters.Filters.Add(new PerformanceTestFilter());

You can get details about the controller being tested from the filterContext parameter.

UPDATE

Adding the filter to the GlobalFilters collection directly will create a single instance of the filter for all actions. This, of course, will not work for timing concurrent requests. To create a new instance for each action, create a filter provider:

public class PerformanceTestFilterProvider : IFilterProvider
{
    public IEnumerable<Filter> GetFilters(ControllerContext controllerContext, ActionDescriptor actionDescriptor)
    {
        return new[] {new Filter(new PerformanceTestFilter(), FilterScope.Global, 0)};
    }
}

Then instead of adding the filter directly, rather add the filter provider in Application_Start():

FilterProviders.Providers.Add(new PerformanceTestFilterProvider());

Solution 2

I usually add this simple code to the bottom of my Layout view:

<!-- Page generated in @((DateTime.UtcNow - HttpContext.Current.Timestamp.ToUniversalTime()).TotalSeconds.ToString("F4")) s -->

Outputs something like:

<!-- Page generated in 0.4399 s -->

This starts measuring when the HttpContext is created (according to the documentation), and stops right before writing to output, so it should be pretty accurate.

It might not work for all use cases (if you want to measure child actions, or ignore the time outside the MVC action, etc.), but it's easy to paste into a view.

For more advanced diagnostics, I used to use Glimpse.

Solution 3

Try ASP.NET 4.5 Page Instrumentation

It instruments page rendering: The time of your app might be spent in the controller, but there are lots of times where it is spent in the viewrendering. Especially if you have lots of partials and html helpers.

Comments

[Eric J.]

Sounds promising. I'll give that a shot. An instance of PerformanceTestFilter is created for each action I presume (so that it has it's own Stopwatch instance)?

[Kevin Aenmey]

Actually... it doesn't. You need to create an IFilterProvider for that. See my updated answer.

[user1068352]

Tip: Stopwatch has Restart method.

[Brian Low]

I couldn't find the global action filter in the tutorial. Tried searching for "global", "filter" and "timer" with no hits.

[RickAndMSFT]

added global filter to my answer

[Guillaume86]

You could also use filterContext.HttpContext.Items to store your stopwatch and get it back after (and actionContext.Request.Properties for WebApi filters).

[Imran Qadir Baksh - Baloch]

Isn't race condition there? If multiple requests use the same filter instance bradwilson.typepad.com/blog/2010/07/…

[aruno]

Tip: put stopWatch=null at the end of OnActionExecuted so you can be sure you're getting a new instance. If you get an exception you'll know the instance is being reused