Temps de traitement de la demande de journal ASP.Net MVC AsyncController

Question

Je dois obtenir le temps de traitement des demandes pour asp.net MVC. J'utilise l'abonnement IHttpModule pour les événements onBeginRequest et onEndRequest. Pour les contrôleurs de synchro, cela fonctionne très bien mais pour async il renvoie un mauvais résultat (par exemple 20ms quand le temps réel était d'environ 2min). Comment puis-je obtenir le temps de traitement des demandes pour AsyncController de manière générale (ne pas écrire de code supplémentaire dans ActionAsync/ActionCompleted pour chaque action asynchrone)?

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

C'est très étrange. Normalement, ce scénario devrait fonctionner. Malheureusement, vous n'avez pas montré votre code, il est donc difficile de dire ce que vous pourriez faire de mal.

De plus, je suis incapable de le reproduire. Voici le module que j'ai écrit à tester:

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

qui je me suis inscrit dans mon web.config (je testé sous Cassini, si vous avez l'intention d'utiliser IIS 7, vous devrez enregistrer le module dans la section <system.webServer> respective):

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

Et puis écrit un contrôleur de l'échantillon à tester:

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

Je tiré deux requêtes HTTP parallèles aux urls suivantes:

• /home/index
• /home/indexsync

Les 2 demandes traitées comme prévu au bout de 5 secondes et le fichier journal avait l'air parfaitement normal:

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

Comme vous pouvez le voir le module HTTP mesuré le temps d'exécution des deux actions asynchrones et synchrones correctement.

Alors qu'est-ce qui donne? En passant, vous pouvez vérifier MiniProfiler et vous assurer qu'il n'y a pas de réinvention de roue pour votre scénario.