15

I am using an ActionFilter to log all action calls of my ASP.NET Web API project. The OnActionExecuted method tells a lot about what's been happening.

I just can't figure out how to find an efficient way to measure execution time...

Kiquenet
  • 14,494
  • 35
  • 148
  • 243
RooSoft
  • 1,481
  • 2
  • 17
  • 32

2 Answers2

36

Something like this should do the trick...

public class StopwatchAttribute : ActionFilterAttribute
{
    private const string StopwatchKey = "StopwatchFilter.Value";

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        base.OnActionExecuting(actionContext);

        actionContext.Request.Properties[StopwatchKey] = Stopwatch.StartNew();
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        base.OnActionExecuted(actionExecutedContext);

        Stopwatch stopwatch = (Stopwatch)actionExecutedContext.Request.Properties[StopwatchKey];
        // TODO something useful with stopwatch.Elapsed
        Trace.WriteLine("Elapsed = " + stopwatch.Elapsed);
    }
}

Here we store a new Stopwatch in the request properties and stop it when the request has completed.

Dean Ward
  • 4,793
  • 1
  • 29
  • 36
  • Why do u save the instance in the request ? Why don't u make it a private field ? – user49126 Sep 23 '14 at 17:35
  • 5
    @user49126 Action filters are shared across multiple actions and there could be multiple in-flight requests. To eliminate concurrency concerns it is safest to store the instance on the request. – Dean Ward Sep 24 '14 at 10:59
  • 1
    Also there is an improved solution stays here [link](http://stackoverflow.com/questions/14062028/how-to-intercept-all-the-asp-net-webapi-controller-action-methods-calls-with-nin) – zapoo Aug 05 '15 at 12:06
  • Does this work for async methods? i.e. If using async then will this time the duration of the call including all continuations until the bytes are written to the response stream? – Luke Puplett Oct 23 '15 at 15:02
  • @LukePuplett `Stopwatch` works by taking a snapshot of the system ticks when started and computing the difference from that snapshot when queried. In this case though we're using an action filter so it only includes the time that it takes to execute the action itself. If you need to get timing information for the full request you should look into the [Tracing](http://www.asp.net/web-api/overview/testing-and-debugging/tracing-in-aspnet-web-api) API instead. – Dean Ward Oct 24 '15 at 19:02
  • @DeanWard Thanks for answering, Dean. I was worried that the action executed 'event' would occur only when the Task is returned from an action, but I put a test together and the WebAPI calls `OnActionExecuted` when the top task completes, which is accurate enough. – Luke Puplett Oct 26 '15 at 09:00
  • This doesn't take into consideration other filters or message handlers or delegating handlers. How can you time the _entire_ request and still know which controller/action loaded? – BradLaney Jun 05 '17 at 09:40
  • @BradLaney addressed in another comment; use the [Tracing](https://learn.microsoft.com/en-us/aspnet/web-api/overview/testing-and-debugging/tracing-in-aspnet-web-api) API instead. Or use something earlier in the pipeline like an HTTP module. – Dean Ward Jun 05 '17 at 09:56
0

You will need these using statements to run the above example:

using System.Diagnostics;
using System.Web.Http.Controllers;
using System.Web.Http.Filters;

I registered the filter globally for my whole api in WebApiConfig class like this: config.Filters.Add(new StopwatchAttribute());

and in case you want to print out the name of the controller with the elapsed time, here is how you can get the name of the controller in the OnActionExectued method:

string ControllerName = actionExecutedContext.ActionContext.ActionDescriptor.ControllerDescriptor.ControllerName;
Ephie
  • 229
  • 2
  • 13