Can You Spot the Bug?

Ouch.  I hate mistakes like this.

I decided over the weekend to take a step back and do some performance monitoring of my site.  I've noticed the performance has slowly been degrading over the months, and I wanted to see why.  In truth, with shared hosting (which is what I'm on) there is only so much you can do, but there are always optimizations to be made.  I have my own analytics engine that makes both a performance chart and a traffic chart

In looking at the charts, the performance started to trend upwards around April of '07 -- which is interesting because traffic also took a big dip that month.  It could be the hosting provider had service issues, brought on more clients, or something during that time.  The charts don't quite provide enough detail -- so I dove into some queries to look at things.  In some future posts, I'd like to do a series on performance tuning .NET and SQL applications, but to keep this post on topic, I realized I had a fairly major bug.  Some folks have asked me: how do you measure page performance/generation time in your charts? 

What I do is stuff the current time in the HttpContext in an HttpModule's Application_BeginRequest event.  Then, in the Application_EndRequest, I create a timespan of the difference.  The timespan, then, records the amount of time it took to create the page.  I convert the timespan into milliseconds since that's the only value I care about.  I happen to log this data -- what you do with it is somewhat up to you -- you could, for example, only log pages that take > 500 milliseconds, so you know you have an issue with a page.  Clearly, there are huge scalability issues so you have to be careful with how you log the data.

But I digress. 

Here's the relevant code, with extraneous parameters stripped out.  Now that you know what it is supposed to do, can you spot the bug?

Application_BeginRequest:

System.Web.HttpContext.Current.Items.Add("beginrequest", DateTime.Now);

Application_EndRequest:

TimeSpan pageGenTime =
        DateTime.Now.Subtract((DateTime)Context.Items["beginrequest"]);

//call to the logging method
LogRequest( ... , ... , pageGenTime.Milliseconds, ... , ...);

Here's a hint:  most of the time, I'd say, probably all of the time, the behavior is as expected.  I'll follow up shortly with how I (finally, after a year or more) caught it.

EDIT:  I highlighted the bug above in red.  The mistake is accessing the Milliseconds property instead of TotalMilliseconds.  Obviously, this only returns the milliseconds portion, when in reality I wanted the total timespan represented in milliseconds.  The end result is that no page would ever be more than 999 milliseconds ... worse still, if a page renders in (for example) 00:00:01.002, it would show as 2 milliseconds.   How was this eventually caught?  Sadly, it took almost 2 years, and was caught while debugging the application.  I looked at the log files, and realized that despite sitting on a break point for many seconds, the page miraculously rendered in only a few milliseconds. 

Comments (1) -

Tanner
Tanner
1/29/2008 12:50:12 PM #

I was looking at doing something similar to this the other day.  You just saved me a bit of time.

I look forward to future stuff on performance tuning .net apps and sql stuff.

Comments are closed

My Apps

Dark Skies Astrophotography Journal Vol 1 Explore The Moon
Mars Explorer Moons of Jupiter Messier Object Explorer
Brew Finder Earthquake Explorer Venus Explorer  

My Worldmap

Month List