ASP.Net MVC AsyncController 日志请求处理时间

Question

我需要获取 asp.net MVC 的请求处理时间。我使用 IHttpModule 订阅 onBeginRequest 和 onEndRequest 事件。对于同步控制器，它工作得很好，但对于异步，它返回错误的结果（例如，当实时时间约为 2 分钟时为 20 毫秒）。如何以一般方式获得 AsyncController 的请求处理时间（不在 ActionAsync/ActionCompleted 中为每个异步操作编写附加代码）？

public class TrackRequestModule : RequestProcessingModuleBase, IHttpModule
{
    public const string BeginRequestTimeKey = "beginRequestTime";

    public void Init(HttpApplication context)
    {
        if (context == null)
        {
            throw new ArgumentNullException("context");
        }

        context.BeginRequest += onBeginRequest;
        context.EndRequest += onEndRequest;
    }

    private void onEndRequest(object sender, EventArgs e)
    {
        InvokeHandler(sender, OnEndRequest);
    }

    private void onBeginRequest(object sender, EventArgs e)
    {
        InvokeHandler(sender, OnBeginRequest);
    }

    public void OnBeginRequest(HttpContextBase context)
    {
        context.Items[BeginRequestTimeKey] = DateTime.Now.ToLocalTime();
    }

    public void OnEndRequest(HttpContextBase context)
    {
        var beginRequestTime = (DateTime)context.Items[BeginRequestTimeKey];
        TimeSpan elapsedTime = DateTime.Now.ToLocalTime() - beginRequestTime;

        var info = new RequestData
                    {
                        BeginTime = beginRequestTime,
                        ElapsedTimeMilliseconds = elapsedTime.Milliseconds,
                        Url = context.Request.Url.AbsoluteUri,
                        Data = GetRequestData(context.Request)
                    };
        ThreadPool.QueueUserWorkItem(logRequestInfo, info);
    }

    public void Dispose() { }

    private void logRequestInfo(object state)
    {
        var info = (RequestData)state;
        var queryStore = ObjectBuilder.Instance.Resolve<IRequestTrackingDataQueryStore>();
        queryStore.SaveRequestTrackingData(info.BeginTime, info.ElapsedTimeMilliseconds, info.Url, info.Data);
    }

    private sealed class RequestData
    {
        public DateTime BeginTime { get; set; }
        public int ElapsedTimeMilliseconds { get; set; }
        public string Url { get; set; }
        public string Data { get; set; }
    }
}

Answer 1

这很奇怪。通常这种情况应该有效。不幸的是，您还没有展示您的代码，因此很难说出您可能做错了什么。

此外我无法重现它。这是我编写的用于测试的模块：

public class MeasureModule : IHttpModule
{
    private static readonly ReaderWriterLockSlim _gateway = new ReaderWriterLockSlim();

    public void Dispose()
    {
    }

    public void Init(HttpApplication context)
    {
        context.BeginRequest += (sender, e) =>
        {
            var app = (sender as HttpApplication);
            var watch = Stopwatch.StartNew();
            app.Context.Items["watch"] = watch;
        };

        context.EndRequest += (sender, e) =>
        {
            var app = (sender as HttpApplication);
            var watch = app.Context.Items["watch"] as Stopwatch;
            watch.Stop();
            var url = app.Context.Request.Url.AbsoluteUri;
            var message = string.Format("url: {0}, time: {1}ms", url, watch.ElapsedMilliseconds);
            var log = HostingEnvironment.MapPath("~/log.txt");
            _gateway.EnterWriteLock();
            try
            {
                File.AppendAllLines(log, new[] { message });
            }
            finally
            {
                _gateway.ExitWriteLock();
            }
        };
    }
}

我在我的 web.config 中注册的（我在 Cassini 下测试过，如果你打算使用 IIS 7，你必须在相应的<system.webServer>部分注册模块）：

<httpModules>
  <add name="measure" type="MvcApplication.Modules.MeasureModule, MvcApplication" />
</httpModules>

然后写了一个示例控制器来测试：

[SessionState(SessionStateBehavior.Disabled)]
public class HomeController : AsyncController
{
    public ActionResult IndexSync()
    {
        Thread.Sleep(5000);
        return Content("completed", "text/plain"); 
    }

    public void IndexAsync()
    {
        AsyncManager.OutstandingOperations.Increment();
        Task.Factory.StartNew(() =>
        {
            Thread.Sleep(5000);
            AsyncManager.OutstandingOperations.Decrement();
        });
    }

    public ActionResult IndexCompleted()
    {
        return Content("completed", "text/plain");
    }
}

然后我向以下网址发出了两个并行的 HTTP 请求：

• /home/index
• /home/indexsync

2 个请求在大约 5 秒后按预期完成，日志文件看起来完全正常：

url: http://localhost:14953/home/index, time: 5047ms
url: http://localhost:14953/home/indexsync, time: 5005ms

如您所见，HTTP 模块正确测量了异步和同步操作的执行时间。

那么什么给呢？

顺便说一句，您可能会检查MiniProfiler并确保您的场景没有轮子重新发明。