ASP.Net MVC AsyncController log request processing time

Question

I need to get request processing time for asp.net MVC. i use IHttpModule subscribing for onBeginRequest and onEndRequest events. For sync controllers it works great but for async it returns wrong result(for example 20ms when real time was about 2min). How could I get request processing time for AsyncController in general way(not writing aditional code in ActionAsync/ActionCompleted for each async action)?

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

That's very strange. Normally this scenario should work. Unfortunately you haven't shown your code so it is difficult to say what you might be doing wrong.

Besides I am unable to reproduce it. Here's the module I wrote to test:

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

Which I registered in my web.config (I tested under Cassini, if you intend to use IIS 7 you will have to register the module in the respective <system.webServer> section):

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

And then wrote a sample controller to test:

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

Then I fired two parallel HTTP requests to the following urls:

• /home/index
• /home/indexsync

The 2 requests completed as expected after about 5 seconds and the log file looked perfectly normal:

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

As you can see the HTTP module measured the execution time of both the asynchronous and synchronous actions correctly.

So what gives?

By the way you might checkout MiniProfiler and ensure that there are no wheel reinventions for your scenario.