Measuring performance of ASP.NET MVC 3

Question

I've built a JSON service in ASP.NET MVC 3 and I want to be able to measure the execution time of the actions in my application (I want to it to automatically log slow actions).

Therefor this looked great; http://coderjournal.com/2010/10/timing-the-execution-time-of-your-mvc-actions/ (It's been mentioned on places here on stack overflow as well)

The problem is that I get measurements that MUST be wrong from this method; I've added another stopwatch that starts the first thing in the action and stops just before the return.

Example:

Stopwatch inside the method => 10ms (the serializing to json is omitted here, so I can understand that it's shorter than reality)
Stopwatch attribute (code above) => 676ms
Firefox says the request took => 70ms .

I believe that firefox has the correct time here (but it includes the download so it's a bit large), but I want to understand why the attribute code doesn't work, any ideas for this?

Yeah, and the cache is off in Firefox... – ullmark Apr 28 '11 at 15:52 — ullmark, Apr 28 '11 at 15:52

score 16 · Accepted Answer · edited Jun 26 '12 at 18:01

16

This might not be the reason why it shows that long execution time, but that attribute won't work correctly with mvc 3 when you have multiple requests at once.

In previous versions of ASP.NET MVC, action filters are create per request except in a few cases. This behavior was never a guaranteed behavior but merely an implementation detail and the contract for filters was to consider them stateless. In ASP.NET MVC 3, filters are cached more aggressively. Therefore, any custom action filters which improperly store instance state might be broken.

I'd recommend to instantiate new stopwatch in OnActionExecuting and save it to HttpContext.Current.Items - then you can retrieve it in OnActionExecuted and print out result.

edited Jun 26 '12 at 18:01

Jim G.

15,141
22
103
166

answered Apr 28 '11 at 18:53

Lukáš Novotný

9,012
3
38
46

You were correct, since the actions are cached, the constructor is only run once in a while, so the same stopwatch is reused. – ullmark May 02 '11 at 08:05
1

The code in question [has been updated](https://github.com/managedfusion/managedfusion-web/blob/master/src/Web/Mvc/StopwatchAttribute.cs) and now works as Lukáš Novotný suggested. – Fernando Correia May 20 '12 at 00:59
This does not return reliable results as the view is rendered afterwards that could call ChildActions – MichaelD Dec 30 '15 at 11:02

score 8 · Answer 2 · edited May 23 '17 at 12:00

More correct approach in addition to answer https://stackoverflow.com/a/5823555/504082 is to use OnResultExecuted override at the end of clock execution. When you return

ActionResponse.Success(arr.Select(x => func(x)).ToJson();

i.e. some lazy LINQ statement as a result of your action, it will be calculated after action is "executed" (function 'func' execution will not be count towards action execution time). I've got this nasty bug and couldn't figure out why my action "execution time" is 100 ms although web request executes 10 seconds. Modified code below.

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Web;
using System.Web.Mvc;

namespace SW
{
    public class StopwatchAttribute : ActionFilterAttribute
    {
        public override void OnActionExecuting(ActionExecutingContext filterContext)
        {
            var stopwatch = new Stopwatch();
            filterContext.HttpContext.Items["Stopwatch"] = stopwatch;

            stopwatch.Start();
        }

        public override void OnResultExecuted(ResultExecutedContext filterContext)
        {
            var stopwatch = (Stopwatch)filterContext.HttpContext.Items["Stopwatch"];
            stopwatch.Stop();

            var httpContext = filterContext.HttpContext;
            var response = httpContext.Response;

            response.AddHeader("X-Runtime", stopwatch.Elapsed.TotalMilliseconds.ToString());
        }
    }
}

Ermagherd, this is awesome. Do you know if it's possible to separate this from `ActionFilterAttribute` so that it could be used for any method? I figured I'd just put a name property for the attribute to keep track of various stopwatches or log one and kill it at EndRequest but I can't figure out how to grab to a "OnResultExecuted" event for non-actions. — Joel Peltonen, Apr 29 '13 at 10:05
This is great if you want to have a "debug" console in the webpage — Kat Lim Ruiz, Sep 11 '13 at 17:24

score 1 · Answer 3 · answered Apr 28 '11 at 16:19

1

Why not have a look at page performance module from Rhino commons?

answered Apr 28 '11 at 16:19

suhair

10,895
11
52
63

score 0 · Answer 4 · answered Apr 28 '11 at 17:30

0

Looks like you are off by an order of magnitude. Are you sure you are reading the result correctly? Try using the Stopwatch.ElapsedMilliseconds property.

answered Apr 28 '11 at 17:30

marcind

52,944
13
125
111

Measuring performance of ASP.NET MVC 3

4 Answers4

Linked