Stopwatch Threshold Logging

Today's post is not related to regular expressions at all. In fact it's not really related to Regex Hero except that it potentially affects the website. But I figure I'd write about it here anyway.

I've been diagnosing some intermittent web server performance issues for awhile now. And in effort to gain some insight into which pages are slow and how often, I wrote a simple logger.

The idea is to time the ASP.NET page lifecycle from start to finish, and if it exceeds a certain threshold, then log it. The advantage of this approach is that it's not going to waste processing time logging the stuff I don't care about.

If you're interesting in this for yourself and you're running ASP.NET all you'd have to do is add the following to your global.asax:

private Stopwatch sw; protected void Application_BeginRequest() { sw = new Stopwatch(); sw.Start(); } protected void Application_EndRequest() { sw.Stop(); if (sw.ElapsedMilliseconds > 500) // 500 ms threshold { try { StringBuilder sb = new StringBuilder(); sb.AppendLine(DateTime.Now.ToUniversalTime().ToString()); sb.AppendLine(Request.Path); sb.AppendLine(sw.ElapsedMilliseconds + " ms"); sb.AppendLine(Environment.NewLine); System.IO.File.AppendAllText(Server.MapPath(@"~\App_Data\StopwatchLogger.txt"), sb.ToString()); } catch { } } }

The Application_BeginRequest and Application_EndRequest events are the first and last events in the page lifecycle, respectively. So this does a beautiful job of timing every single request throughout your web application, while only logging the slow stuff.

The result of a logged event might look like this:

4/10/2010 3:56:01 AM
/default.aspx
995 ms

Super simple and to the point. You could easily expand on this code if you wanted, adding get and post request variables, cookies or whatever might help you put this into context.

To test this initially I recommend setting the threshold to 1 ms just to make sure the logging works without throwing an error. Once you verify that you can set it back to something more reasonable like 500 ms and let it do its thing.