Geeks With Blogs
Chris Falter .NET Design and Best Practices

Last week we went through a "fire drill" when users of one of our web applications started receiving "Gateway Timeout" errors (HTTP Error 504).  This error indicates that a gateway "server" (any host that forwards the HTTP request, including a router or web server) did not receive a timely response from a server that is supposed to respond.  Naturally we didn't have a clue as to which host in the connection chain from users' browsers to our web farm was reporting the error, but the leading candidate for the ultimate culprit was our web application.  Hence the fire drill; I had to do whatever it took to find out what might be causing a slow response.  Well, there went my 4th of July celebration!

A quick Performance Monitor analysis showed that the web servers and web application were not causing any delays.  Average CPU utilization was less than 6%, and the web application itself does not have any shared internal resources that could serve as a bottleneck.  So if there was a bottleneck, it had to be in the interface between our web application and some external resource. 

That in turn meant that I had to insert instrumentation code to log the time spent in those interfaces.  In the .NET Framework 2.0, you accomplish this with the System.Diagnostics.Stopwatch class:

Stopwatch timerCall = null;

string rawResult = String.Empty;

try
{
    
VendorProxy p = new VendorProxy();
    
if (useTimers)
    {
        timerCall =
new Stopwatch();
        timerCall.Start();
    }
    rawResult = p.GetVendorData(reqText);
}
finally
{
    
if (useTimers)
    {
        timerCall.Stop();
        
Trace.WriteLine(
            
DateTime.Now.ToString() + "," +
            responseType +
"," +
            seibelsId +
"," +
            timerCall.ElapsedMilliseconds.ToString()
            );
        
Trace.Flush();
    }
}

In the class' static constructor, we set the value of the useTimers boolean according to a BooleanSwitch in the web.config :

private static bool useTimers;
static VendorGatewayService()
{
    
BooleanSwitch timerLoggingSwitch = new BooleanSwitch("TimerLogging", "Determines whether to log timing info");
    
if (timerLoggingSwitch.Enabled)
        useTimers =
true;
}

See the MSDN documentation for an example of how to configure a BooleanSwitch in a config file.  Likewise, you may configure a TraceListener in a config file as well. We chose to write our output to a comma-separated value (CSV) file due to its ease of use with Excel.  By logging the responseType (i.e., name of method) and our customer's ID, we would be able to determine which methods might be too slow, and which of our customers were affected.  (After all, they sometimes call to ask questions!)

If your application still uses .NET Framework 1.0 or 1.1, you should use Peter Bromberg's HiPerfTimer class in place of the Stopwatch class.  Do not use the built-in TimeSpan class, whose precision is very poor.  Also, notwithstanding the MSDN documentation, it is impossible to configure a TraceListener in a config file prior to .NET Framework 2.0.  As a result, in my 1.1 web app I added the following key/value pairs in the appSettings element:

<add key="UseTimers" value="true" />
<
add key="TraceLogName" value="c:\\projects\\dev\\agentweb\\mysoln\\1.4\\spweb\\Timer.log" />

Here's how I used them in the Application_Start handler of global.asax.cs:

protected void Application_Start(Object sender, EventArgs e)
{
    
bool useTimers = false;
    
string strUseTimers = ConfigurationSettings.AppSettings["UseTimers"];
    
if (strUseTimers != null)
        useTimers =
Boolean.Parse(strUseTimers);
    
if (useTimers)
    {
        
string traceLogName = ConfigurationSettings.AppSettings["TraceLogName"];
        
if (traceLogName != null && traceLogName != String.Empty)
        {
            StreamWriter file = File.AppendText(traceLogName);
            TextWriterTraceListener log =
new TextWriterTraceListener(file);
            Trace.Listeners.Add(log);
        }
    }
}

 

Now that my colleague/manager Chris Glasser has identified the main bottleneck, I can edit the config files to turn off the logging.  And if another resource contention issue rears its nasty-looking head, I can edit the config files to turn the logging back on.  Very convenient.  (For you Michael Jackson fans, it's as "easy as A-B-C.")

Want to know what the root problem was?  It wouldn't be fair for me to leave my readers hanging, would it?  Okay, you've stuck with me through this article; I'll reward your faithful readership....  The insurance agents' requests were never even reaching our web application due to networking issues at one of big carriers.  When I returned from my delayed vacation, you could almost see the steam come out of my ears when I learned this.  Have any of you ever worked like crazy to solve a problem, only to discover that the root cause was something outside your control?  Leave a comment so we can commiserate!

Posted on Friday, July 13, 2007 7:46 AM Performance & Tuning | Back to top


Comments on this post: How To: Instrument Your Code to Time Its Use of Resources

No comments posted yet.
Your comment:
 (will show your gravatar)


Copyright © Chris Falter | Powered by: GeeksWithBlogs.net