ASP.NET MVC3：在解析视图之前触发 OnActionExecuted答案

【问题标题】：ASP.NET MVC3: OnActionExecuted triggered before parsing the viewASP.NET MVC3：在解析视图之前触发 OnActionExecuted
【发布时间】：2014-03-01 19:54:14
【问题描述】：

我使用此操作过滤器来记录执行每个操作所用的时间（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);
            }
        }
    }
}

似乎在解析视图.cshtml文件之前触发了OnActionExecuted。更准确地说，我调用了以下操作：

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);
}

虽然页面仅在请求后 5000 毫秒提供服务，但日志显示：

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

我不一定对测量网络时间感兴趣（例如，内容流需要多长时间才能发送到客户端）。但是这里的问题是，yield-lazy-evaluation 可能会隐藏一个缓慢的数据库查询，这显然必须被日志考虑在内。

那么，在这种情况下，如何在日志中写入 5000 毫秒？

【问题讨论】：

标签： c# asp.net-mvc-3 log4net actionfilterattribute

【解决方案1】：

我认为你需要OnResultExecuting/ed 而不是OnActionExecuting/ed。

OnActionExecuting在决定动作后但在执行之前执行
OnActionExecuted 在操作返回 ActionResult 后执行
OnResultExecuting 在有结果时执行（包括如果另一个过滤器在执行操作之前更改结果，我相信），但在针对 HTTP 响应执行之前执行
OnResultExecuted 在针对 HTTP 响应执行结果后执行

【讨论】：

好提示。我已经尝试过了，但 OnResultExecuting/ed 也对经过的时间做出了部分贡献（例如，如果我将 Sleep() 放在 return View() 之前，则不考虑这一点）。也许正确的解决方案是使用 OnActionExecuting/OnResultExecuted 对小心处理这样一个事实，即在复杂的 Controller/Action 调用中（例如，在中间调用部分视图）它们不是以严格的顺序触发的，而是用嵌套级别。

【解决方案2】：

actionfilter 属性确实在操作之前执行。您看到的时间来自执行过滤器而不是请求。如果你的 match 方法会调用 getdata 3 次，我预计 IDD 需要 5 秒。

【讨论】：