HttpModule For Timing Requests

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.

Technorati Tags: ,,

What others have said

Requesting Gravatar... Steve Smith Jul 02, 2008 1:24 AM
# re: HttpModule For Timing Requests
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.
Requesting Gravatar... Brian Canzanella Jul 02, 2008 2:34 AM
# re: HttpModule For Timing Requests
What about using preprocessor directives to limit the number of changes that need to be made when going from debug to release?
Requesting Gravatar... edddy Jul 02, 2008 4:10 AM
# re: HttpModule For Timing Requests
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

Requesting Gravatar... Travis Jul 02, 2008 5:46 AM
# re: HttpModule For Timing Requests
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?
Requesting Gravatar... Al Pascual Jul 02, 2008 6:22 AM
# re: HttpModule For Timing Requests
What about just enabling trace="true"?
Requesting Gravatar... BigJimInDC Jul 02, 2008 6:44 AM
# re: HttpModule For Timing Requests
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...
Requesting Gravatar... hhrvoje Jul 02, 2008 6:50 AM
# re: HttpModule For Timing Requests
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.
Requesting Gravatar... Yash Jul 02, 2008 7:18 AM
# re: HttpModule For Timing Requests
Good, but not an esoteric post.
Requesting Gravatar... defeated Jul 02, 2008 7:49 AM
# re: HttpModule For Timing Requests
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?
Requesting Gravatar... Meisinger Jul 02, 2008 8:10 AM
# re: HttpModule For Timing Requests
@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
Requesting Gravatar... Meisinger Jul 02, 2008 8:17 AM
# re: HttpModule For Timing Requests
@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)
Requesting Gravatar... Jeff Atwood Jul 02, 2008 8:42 AM
# re: HttpModule For Timing Requests
I suspect this doesn't work under IIS7 for some reason.. works great locally in Cassini, but nothing on our dev server.
Requesting Gravatar... Jeff Atwood Jul 02, 2008 8:53 AM
# re: HttpModule For Timing Requests
oh, right, you gotta add it to the / section to get it to work in IIS7 -- you should update your post to reflect this.
Requesting Gravatar... Travis Jul 03, 2008 12:04 AM
# re: HttpModule For Timing Requests
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.
Requesting Gravatar... aspcode.net Jul 03, 2008 5:17 AM
# re: HttpModule For Timing Requests
[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.
Requesting Gravatar... JW Jul 08, 2008 7:21 AM
# re: HttpModule For Timing Requests
Very neat tricky to measure the actual time of the page request, exactly something what I am looking for. Thanks for sharing.
Requesting Gravatar... Tom Fanning Jul 12, 2008 12:29 AM
# re: HttpModule For Timing Requests
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?
Requesting Gravatar... haacked Jul 13, 2008 1:03 AM
# re: HttpModule For Timing Requests
@Tom It provides more precision and it's higher performant, which can lead to more accuracy as well.
Requesting Gravatar... Kevin Babcock Jul 23, 2008 7:47 AM
# re: HttpModule For Timing Requests
Great post! Thanks for sharing!
Requesting Gravatar... AG Jul 25, 2008 4:52 AM
# re: HttpModule For Timing Requests
Will this work with asp.net mvc? As I understand it asp.net mvc doesnt have page lifecycle like web forms based stuff.
Requesting Gravatar... haacked Jul 25, 2008 11:43 AM
# re: HttpModule For Timing Requests
@AG Yes it does work with MVC. There is still a Request lifecycle.
Requesting Gravatar... Tim Barcz Aug 12, 2008 11:49 AM
# re: HttpModule For Timing Requests
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
Requesting Gravatar... John Sep 17, 2008 6:07 AM
# re: HttpModule For Timing Requests
You could also use:

void Application_EndRequest()
{
Response.Write("Time Elapsed: " + DateTime.Now.Subtract(HttpContext.Current.Timestamp).TotalMilliseconds);
}
Requesting Gravatar... Peter Bucher Nov 03, 2008 6:52 AM
# re: HttpModule For Timing Requests
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
Requesting Gravatar... tecfield Feb 20, 2010 7:57 AM
# re: HttpModule For Timing Requests
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.
Requesting Gravatar... Billb Feb 26, 2010 1:55 AM
# re: HttpModule For Timing Requests
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:))
Requesting Gravatar... DS Jan 14, 2011 12:13 AM
# re: HttpModule For Timing Requests
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...!!
Requesting Gravatar... Adam dudley May 26, 2011 5:55 PM
# re: HttpModule For Timing Requests
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!

What do you have to say?

(will show your gravatar)
Please add 8 and 8 and type the answer here: