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?

Locoweed

Answer 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());

Saudra

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)? – Locoweed

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

Tip: Stopwatch has Restart method. – Noneffective

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

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

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 – Belenbelesprit

Answer 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.

Revulsive

Answer 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.

Eudora

Answer 4

Update - install my Stopwatch NuGet package with Install-Package StopWatch see Profile and Time your ASP.NET MVC app all the way to Azure

See my tutorial Using Asynchronous Methods in ASP.NET MVC 4 which has a global action filter timer. You could use ELMAH to log the data. My sample My sample http://msdn.microsoft.com/en-us/library/gg416513(v=vs.98) also has the same timing filter and is simpler, but it's pre-Razor.

Look for the stop watch attribute to enable timing.

public class FilterConfig
{
    public static void RegisterGlobalFilters(GlobalFilterCollection filters)
    {
        filters.Add(new HandleErrorAttribute());
        filters.Add(new UseStopwatchAttribute());
    }
}

Groan

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

added global filter to my answer – Groan