Время обработки запроса журнала ASP.Net MVC AsyncController

Question

Мне нужно получить время обработки запроса для asp.net MVC. Я использую IHttpModule для подписки на события onBeginRequest и onEndRequest. Для контроллеров синхронизации он отлично работает, но для async он возвращает неверный результат (например, 20 мс, когда в реальном времени было около 2 мин). Как я могу получить время обработки запроса для 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 (я тестировал под Кассини, если вы собираетесь использовать 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 и убедиться, что для вашего сценария нет никаких повторений колес.