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?