ASP.NET MVC3: OnActionExecuted triggered before parsing the view

Question

I use this action filter to log time elapsed executing every action (available here):

public class LoggingFilterAttribute : ActionFilterAttribute
{
    protected static readonly log4net.ILog log = log4net.LogManager.GetLogger("PerfLog");
    private const string StopwatchKey = "DebugLoggingStopWatch";

    public override void OnActionExecuting(ActionExecutingContext filterContext)
    {
        if (log.IsDebugEnabled)
        {
            var loggingWatch = Stopwatch.StartNew();
            filterContext.HttpContext.Items.Add(StopwatchKey, loggingWatch);

            log.DebugFormat("Action started: {0}/{1}",
                filterContext.ActionDescriptor.ControllerDescriptor.ControllerName,
                filterContext.ActionDescriptor.ActionName);
        }
    }

    public override void OnActionExecuted(ActionExecutedContext filterContext)
    {
        if (log.IsDebugEnabled)
        {
            if (filterContext.HttpContext.Items[StopwatchKey] != null)
            {
                var loggingWatch = (Stopwatch)filterContext.HttpContext.Items[StopwatchKey];
                loggingWatch.Stop();

                long timeSpent = loggingWatch.ElapsedMilliseconds;

                log.DebugFormat("Action started: {0}/{1} - Elapsed: {2}ms",
                    filterContext.ActionDescriptor.ControllerDescriptor.ControllerName,
                    filterContext.ActionDescriptor.ActionName,
                    timeSpent);

                filterContext.HttpContext.Items.Remove(StopwatchKey);
            }
        }
    }
}

It seems that OnActionExecuted is triggered before parsing the view .cshtml file. More precisely I called the following action:

private IEnumerable<string> GetData()
{
    yield return "Item1";
    Thread.Sleep(2500);
    yield return "Item2";
    Thread.Sleep(2500);
    yield return "Item3";
}

public ActionResult TestPerf()
{
    var model = GetData();
    return View(model);
}

While the page is served only 5000ms after the request, the log shows:

2014-03-01 20:25:41,630 [12] DEBUG PerfLog - Action started: Test/TestPerf
2014-03-01 20:25:41,632 [12] DEBUG PerfLog - Action finished: Test/TestPerf - Elapsed: 2ms

I am not necessarily interested in measuring network times (e.g. how long the content stream takes to be sent to the client). But the problem here is that yield-lazy-evaluation might hide a slow database query, which obviously has to be taken into account by the log.

So, how can I get 5000ms written within the log in this case?

Answer 1

I think you need OnResultExecuting/ed rather than OnActionExecuting/ed.

• OnActionExecuting executes once the action has been decided upon but before it is executed
• OnActionExecuted executes after the action has returned an ActionResult
• OnResultExecuting executes once there is a result (including if another filter changes the result before the action was executed, I believe), but before it has been executed against the HTTP response
• OnResultExecuted executes after the result has been executed against the HTTP response

Answer 2

The actionfilterattribute indeed executes before the action. The times you see are from executing the filter not the request. If your match method would call getdata 3 times I would IDD expect 5 seconds.