ASP.Net MVC AsyncController日誌請求處理時間

Question

我需要獲取asp.net MVC的請求處理時間。我使用IHttpModule訂閱onBeginRequest和onEndRequest事件。對於同步控制器來說，它的工作效果很好，但對於異步它會返回錯誤的結果（例如實時約爲2分鐘時爲20ms）。我怎樣才能以通常的方式獲取AsyncController的請求處理時間（不是在ActionAsync/ActionCompleted中爲每個異步操作編寫aditional代碼）？

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註冊（我卡西尼下進行測試，如果你打算使用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並確保您的方案沒有車輪改造。