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?

Answer 1

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.