HttpModule For Timing Requests

aspnetmvc 0 comments suggest edit

Yesterday, I wrote a quick and dirty ASP.NET HttpModule for displaying the time that a request takes to process. Note that by turning on trace output for a page, you can get timing information for that page. But as far as I understand, and I need to double check this, this only applies to the page lifecycle, which might not have all the information you want in the context of ASP.NET MVC.

Not to mention, I just wanted to see a simple number at the end of the page and not have to wade through all that trace output. Also keep in mind that this number only applies to the time spent in the ASP.NET pipeline. It obviously doesn’t tell you the full time of the request from browser sending the request to the browser rendering the response. For that I would use something like Firebug in Firefox.

Here’s the code for the module. Note that it only works from local requests in Debug mode. That’s a safety precaution so that if someone accidentally deploys this to a production machine, they won’t see this number at the bottom.

using System;
using System.Diagnostics;
using System.Web;

public class TimingModule : IHttpModule {
  public void Dispose() {
  }

  public void Init(HttpApplication context) {
    context.BeginRequest += OnBeginRequest;
    context.EndRequest += OnEndRequest;
  }

  void OnBeginRequest(object sender, System.EventArgs e) {
    if (HttpContext.Current.Request.IsLocal 
        && HttpContext.Current.IsDebuggingEnabled) {
      var stopwatch = new Stopwatch();
      HttpContext.Current.Items["Stopwatch"] = stopwatch;
      stopwatch.Start();
    }
  }

  void OnEndRequest(object sender, System.EventArgs e) {
    if (HttpContext.Current.Request.IsLocal 
        && HttpContext.Current.IsDebuggingEnabled) {
      Stopwatch stopwatch = 
        (Stopwatch)HttpContext.Current.Items["Stopwatch"];
      stopwatch.Stop();

      TimeSpan ts = stopwatch.Elapsed;
      string elapsedTime = String.Format("{0}ms", ts.TotalMilliseconds);

      HttpContext.Current.Response.Write("<p>" + elapsedTime + "</p>");
    }
  }
}

Notice that I made use of the System.Diagnostics.Stopwatch class, which provides more accuracy than simply calling taking the difference between two calls to DateTime.Now.

In my web.config, I just needed to add the following to the httpModules section (replacing Namespace and AssemblyName with their appropriate values):

<httpModules>
  <!-- ...other modules... -->
  <add name="TimingModule" type="Namespace.TimingModule, AssemblyName" />
</httpModules>

For IIS 7, this configuration would go in the <modules /> section.

Lastly, don’t forget to set your website to debug mode by adding the following in your Web.config. If you want to test your perf in release mode, just remove the IsDebuggingEnabled clause in the module and you don’t need to make the following change.

<compilation debug="true">
<!-- ... -->
</compilation>

Hope you find this useful.

Found a typo or error? Suggest an edit! If accepted, your contribution is listed automatically here.

Comments

avatar

31 responses

  1. Avatar for Steve Smith
    Steve Smith July 1st, 2008

    Nice, I use something similar in a base page class for some of my performance demos in some of my talks. Would be handy to have it as a configurable module to drop into any sample or application.

  2. Avatar for Brian Canzanella
    Brian Canzanella July 1st, 2008

    What about using preprocessor directives to limit the number of changes that need to be made when going from debug to release?

  3. Avatar for edddy
    edddy July 2nd, 2008

    Fast translate for case-sensitive haters (or VB lovers)

    Imports System
    Imports System.Diagnostics
    Imports System.Web

    Public Class TimingModule
    Implements IHttpModule
    Public Sub Dispose() Implements System.Web.IHttpModule.Dispose
    End Sub
    Public Sub Init(ByVal context As System.Web.HttpApplication) Implements System.Web.IHttpModule.Init
    AddHandler context.BeginRequest, AddressOf OnBeginRequest
    AddHandler context.EndRequest, AddressOf OnEndRequest
    End Sub
    Sub OnBeginRequest(ByVal sender As Object, ByVal e As System.EventArgs)
    If (HttpContext.Current.Request.IsLocal AndAlso HttpContext.Current.IsDebuggingEnabled) Then
    Dim stopwatch As New Stopwatch()
    HttpContext.Current.Items("Stopwatch") = stopwatch
    stopwatch.Start()
    End If
    End Sub

    Sub OnEndRequest(ByVal sender As Object, ByVal e As System.EventArgs)
    If (HttpContext.Current.Request.IsLocal AndAlso HttpContext.Current.IsDebuggingEnabled) Then
    Dim stopwatch As Stopwatch = HttpContext.Current.Items("Stopwatch")
    stopwatch.Stop()
    Dim ts As TimeSpan = stopwatch.Elapsed
    Dim elapsedTime As String = String.Format("{0}ms", ts.TotalMilliseconds)
    HttpContext.Current.Response.Write("

    " + elapsedTime + "

    ")
    End If
    End Sub
    End Class

  4. Avatar for Travis
    Travis July 2nd, 2008

    This broken up update panel. I cant perform any async postbacks when I include this http module. Any idea how to get them to work together?

  5. Avatar for Al Pascual
    Al Pascual July 2nd, 2008

    What about just enabling trace="true"?

  6. Avatar for BigJimInDC
    BigJimInDC July 2nd, 2008

    Is the testing of "HttpContext.Current.IsDebuggingEnabled" not redundant, when you can just as well "comment out" the HttpModule XML chunk when you don't want it running? You have to edit the web.config either way.
    And to not impact the actual HTML being returned, why not just do a Debug.WriteLine, or Trace.WriteLine with the DebugTraceListener configured, and fire up DebugView from SysInternals. Those already using something like log4net could just as well configure a logger to filter and direct this output to wherever is desired.
    Just my two cents based on having implemented a nearly identical solution a number of years back...

  7. Avatar for hhrvoje
    hhrvoje July 2nd, 2008

    Again some hidden obscure class that I never knew it exists. I'll have to find .net reference book, probably would see classes for half of my projects and written code.

  8. Avatar for Yash
    Yash July 2nd, 2008

    Good, but not an esoteric post.

  9. Avatar for defeated
    defeated July 2nd, 2008

    This is probably a real noob question (I'm new to HttpModules), but why is the local "stopwatch" variable stored in the Items[] collection instead of a private member of the class?

  10. Avatar for Meisinger
    Meisinger July 2nd, 2008

    @Travis...
    Try checking the content type in the Response of the HttpContext
    If I remember correctly AJAX or XmlHttpRequests should change the content type to something like "text/javascript" or simply "text" where as a normal request would be "text/html" (i might have the switches the wrong way but... you get the point)
    If you see that the content type isn't "text/html" then you would skip the Response.Write method call
    --example in OnEndRequest
    if(HttpContext.Current.Response.ContentType == "text/html"){
    Response.Write("

    " + elapsedTime + "

    ");
    }
    I wonder if you could also check the Request during BeginRequest to gain some insight into the call... don't know
    The problem you are seeing is caused by the Response.Write adding the message in a non "JSON" format.
    hope that helps

  11. Avatar for Meisinger
    Meisinger July 2nd, 2008

    @defeated...
    By putting the StopWatch in the Items collection in becomes available to every piece of code that is executed during the Request
    I actually like this idea
    What you could do then is call "Stop()" on the StopWatch when in your Data Access or Repository layer code so that the times you are getting back excludes database work.
    If the StopWatch is local to the module then you are stuck...
    (I have no idea if that was his intent but... it really sounds good)

  12. Avatar for Jeff Atwood
    Jeff Atwood July 2nd, 2008

    I suspect this doesn't work under IIS7 for some reason.. works great locally in Cassini, but nothing on our dev server.

  13. Avatar for Jeff Atwood
    Jeff Atwood July 2nd, 2008

    oh, right, you gotta add it to the <system.webserver>/<modules> section to get it to work in IIS7 -- you should update your post to reflect this.

  14. Avatar for Travis
    Travis July 2nd, 2008

    Thanks Meisinger,
    That fixed it.
    I added this:

    If HttpContext.Current.Response.ContentType = "text/html" Then
    HttpContext.Current.Response.Write("

    " + ElapsedTime + "

    ")
    End If

    To the OnEndRequest method. It now allows partial page postbacks using an update panel. Although it does not time them.
    I wonder if there is any way to pass it as a JSON format, so we could time the partial page postbacks.

  15. Avatar for aspcode.net
    aspcode.net July 3rd, 2008

    [blockquote]System.Diagnostics.Stopwatch[/blockquote]
    lol...I didn't know that. I have my own StopWatch class using QueryPerformanceCounter for frequency etc in a helper dll. Guess I can remove that now.

  16. Avatar for JW
    JW July 8th, 2008

    Very neat tricky to measure the actual time of the page request, exactly something what I am looking for. Thanks for sharing.

  17. Avatar for Tom Fanning
    Tom Fanning July 11th, 2008
    Notice that I made use of the System.Diagnostics.Stopwatch class, which provides more accuracy than simply calling taking the difference between two calls to DateTime.Now.


    Does this really provide more accuracy? Can you substantiate this?

  18. Avatar for haacked
    haacked July 12th, 2008

    @Tom It provides more precision and it's higher performant, which can lead to more accuracy as well.

  19. Avatar for Kevin Babcock
    Kevin Babcock July 23rd, 2008

    Great post! Thanks for sharing!

  20. Avatar for AG
    AG July 25th, 2008

    Will this work with asp.net mvc? As I understand it asp.net mvc doesnt have page lifecycle like web forms based stuff.

  21. Avatar for haacked
    haacked July 25th, 2008

    @AG Yes it does work with MVC. There is still a Request lifecycle.

  22. Avatar for Tim Barcz
    Tim Barcz August 12th, 2008

    Phil,
    I have had this in our site(s) for awhile, recently though we noticed a javascript error in IE. Turns out that if I comment out the HttpModule the error disappears. What I can deduce is that the somehow the HttpModule outputs info outside of the body and that somehow messes with how the javascript is parsed in the IE dom. I am curious if you or anyone else is getting this behavior.
    If you're interested in seeing more email me and I can explain more

  23. Avatar for John
    John September 17th, 2008

    You could also use:
    void Application_EndRequest()
    {
    Response.Write("Time Elapsed: " + DateTime.Now.Subtract(HttpContext.Current.Timestamp).TotalMilliseconds);
    }

  24. Avatar for Peter Bucher
    Peter Bucher November 3rd, 2008

    I`ve a solution that doing render the executiontime anywhere at the page-output.
    My approach uses a ResponseFilter, look at:
    - www.aspnetzone.de/.../...onse-filter-ausgeben.aspx
    Regards, Peter

  25. Avatar for tecfield
    tecfield February 20th, 2010

    There is an easier way to do this!
    You can simply put the same code in the Global.asax file. It works perfectly and you do not need to attach an http module which chould have some overhead to your server performance.
    DateTime.Now.Ticks & Environment.Ticks do not get updated fast enough - in fact they get updated around every 1ms - to capture small fraction of time. Stopwatch is the only accurate tool that we have in .NET.

  26. Avatar for Billb
    Billb February 25th, 2010

    It looks like if you're using a custom filter, ( : ActionFilterAttribute), to compress your html generated by a view, writing to the response output in an end request event doesn't work. If I learn enough about MVC to understand why, I'll post back, or maybe someone knows. I posted this on Stackoverflow too. (I know Phil Haack knows:))

  27. Avatar for DS
    DS January 13th, 2011

    Good Post..!! Thanks..!!
    I have a Question. Can we add ".ascx" file after first <form> tag and before last </form> tag using HttpModule in MVC? Basically i want to add some dynamic content in each response but couldn't figure out.
    Thanks for any help...!!

  28. Avatar for Adam dudley
    Adam dudley May 26th, 2011

    Thanks for that.
    I've also added this
    public static string GetCurrentLoadTime()
    {
    Stopwatch stopwatch =
    (Stopwatch)HttpContext.Current.Items["Stopwatch"];
    //Didn't find the stopwatch, reutrn something
    if (stopwatch == null) return "";
    //Get a timespand from our stopwatch
    TimeSpan ts = stopwatch.Elapsed;
    //Return a nice string
    return String.Format("{0}.{1}s", ts.Seconds, ts.Milliseconds);
    }

    so that in the footer of my page I can add
    <%= Namespace.TimingModule.GetCurrentLoadTime() %>
    - it always seems to be the same number, so rendering the very last portion of my footer (a bar) can be ignored!

  29. Avatar for Deirdre
    Deirdre June 6th, 2012

    Hi
    The code is great, exactly what I needed however, outputting to the screen is fine, but I want then take the result and pass it to the server as a variable, but I can't read the value, how do I access it?
    I also tried using httpcontextsession to set the value to a variable and then access that variable, but the session is always null
    Can anyone advise please? Thanks
    Deirdre

  30. Avatar for Bob Mills
    Bob Mills June 8th, 2012

    I write a hidden input with class name "requestTimeElapsed". I can then easily get the value via jQuery: $(".requestTimeElapsed").val() .
    VB.net:


    Sub OnEndRequest(ByVal sender As Object, ByVal e As System.EventArgs)
    If (HttpContext.Current.Request.IsLocal AndAlso HttpContext.Current.IsDebuggingEnabled) Then
    Dim stopwatch As Stopwatch = HttpContext.Current.Items("Stopwatch")
    stopwatch.Stop()
    Dim ts As TimeSpan = stopwatch.Elapsed
    Dim elapsedTime As Double = ts.TotalSeconds
    If HttpContext.Current.Response.ContentType = "text/html" Then
    HttpContext.Current.Response.Write(String.Format("<input class='requestTimeElapsed' name='requestTimeElapsed' type='hidden' value='{0}'>", Math.Round(elapsedTime, 2)))
    End If
    End If
    End Sub
  31. Avatar for sweeta
    sweeta September 17th, 2015

    Hi Steve, I am also after some direction /demo which can help me log
    the response times of all the pages in my asp.net web application. Would you
    mind sharing your code or give me an algorithm?