Quick Performance Triage

• Download source - 1.74 KB
• Download demo application - 12.71 KB

Introduction

Your application performs a task and you feel it is taking too long to run. You step through the code but you don't get a good sense of how long some tasks really take. You need to identify what is slow and where you should focus your attention. You believe that one part of the process is the problem, but do you know that for sure?

The process of surveying the problem to figure out where to focus your attention is called Triage.

A couple definitions for triage:

1. A process for sorting injured people into groups based on their need for or likely benefit from immediate medical treatment. Triage is used in hospital emergency rooms, on battlefields, and at disaster sites when limited medical resources must be allocated.
2. A process in which things are ranked in terms of importance or priority.

As developers, we are a limited resource. We only have so much time and attention that we can focus on any given problem. We need to focus our efforts on those areas where the greatest benefit can be derived.

That need is how this solution was born. I needed to identify what pieces of a process were taking the longest to complete so I could focus my efforts on addressing those areas first. I had my suspicions but I wasn't sure.

Example Usage

Let's jump in and see what the result looks like. Accompanying the article is a class that you can take and modify as needed. It is called SimpleTimer.

We can get our timings by just creating a SimpleTimer object in a using block and surround the code we want to time with it. The resulting time is written to the Output window in the Visual Studio IDE.

Simple Sequential Timing

Simple Sequential Timing Code

int i = 0;
using (new SimpleTimer("Counting from 1 to 20,000"))
{
    while (i < 40000) 
    { 
        i++; 
    }
}

using (new SimpleTimer("Sleeping for 1 second"))
{
    Thread.Sleep(1000);
}

Simple Sequential Timing Output

The output information is written to the Output tab of the Visual Studio IDE.

SimpleTimer: Counting from 1 to 20,000 - Start
SimpleTimer: Counting from 1 to 20,000 - End - (1.1459 msec)
SimpleTimer: Sleeping for 1 second - Start
SimpleTimer: Sleeping for 1 second - End - (985.0371 msec)

Nested Timing

Nested Timing Code

using (new SimpleTimer("Nested Example level 0"))
{
    using (new SimpleTimer("Sleep 1/4 second - level 1"))
    {
        Thread.Sleep(250);
    }

    using (new SimpleTimer("Perform a loop and time each iteration - level 1"))
    {
        for (int i = 0; i < 3; i++)
        {
            using (new SimpleTimer(String.Format
		("Loop iteration number {0} - level 2", i)))
            {
                // Sleep 50 msec per iteration
                Thread.Sleep(50);
            }
        }
    }
}

Nested Timing Output

SimpleTimer: Nested Example level 0 - Start
    SimpleTimer: Sleep 1/4 second - level 1 - Start
    SimpleTimer: Sleep 1/4 second - level 1 - End - (238.8218 msec)
    SimpleTimer: Perform a loop and time each iteration - level 1 - Start
        SimpleTimer: Loop iteration number 0 - level 2 - Start
        SimpleTimer: Loop iteration number 0 - level 2 - End - (58.2576 msec)
        SimpleTimer: Loop iteration number 1 - level 2 - Start
        SimpleTimer: Loop iteration number 1 - level 2 - End - (59.0108 msec)
        SimpleTimer: Loop iteration number 2 - level 2 - Start
        SimpleTimer: Loop iteration number 2 - level 2 - End - (57.6705 msec)
    SimpleTimer: Perform a loop and time each iteration - level 1 - 
						End - (186.8717 msec)
SimpleTimer: Nested Example level 0 - End - (430.4766 msec)

How It Works

The SimpleTimer class implements the IDisposable interface. A new instance of the class is created at the top of the using block. No reference to the created object is needed. When code execution reaches the closing brace of the using block, SimpleTimer's Dispose() method is called. This signals the end of the block to time. The elapsed time is computed and output.

Internally, SimpleTimer uses the .NET Stopwatch class along with Trace for managing the output. From the MSDN page on the Stopwatch class, we learn that Stopwatch "Provides a set of methods and properties that you can use to accurately measure elapsed time."

Why Don't Nested Times Add Up?

Looking at the previous Nested Timing Output, we see that the three "Loop iteration" steps sum to 174.9389 msec. The outer "Perform a loop and time each iteration" step clocks in at 186.8717 msec. That's a difference of 11.9328 msec. Where did that other time go?

This is where nested timings must be taken in context. For an individual timing, the last step of creating the SimpleTimer class is starting the Stopwatch. The first step of the Dispose() is stopping the Stopwatch. When nesting calls to SimpleTimer, we need to remember that we are now also timing the execution of our other timing code!

Nested timings can still be valuable but not for strict performance numbers in the outer layers. Nested timings work really well when trying to get a sense of proportion and relative size. Looking again at the Nested Timing Output, we can see that loop we just examined is about 43% of the total time. More than half the time was spent in the "Sleep 1/4 second" area. Remember, our goal here is triage. We want to identify the slowest areas and get a relative idea of how slow it is so we can determine where our development time is best spent.

Commenting Out Tip

While experimenting with timing different areas of code, you can quickly disable a SimpleTimer call with a single comment-line. Just comment out the using statement and you are left with a perfectly valid scoping block. When you don't have to worry about matching up the Start and End code for the timer, it can be pretty easy to sprinkle them around in your code and remove them as needed.

//using (new SimpleTimer("Testing long process"))
{
    // Some task
}

Custom Logging

Following suggestions in the comments, the class and demo project were updated to allow for custom logging implementations. By default, SimpleTimer still writes output using the Trace class. In the interest of keeping this solution accessible to more users, the changes were implemented using a delegate so it remains .NET 2.0 friendly.

The following example demonstrates customizing the logging output. This uses an anonymous method but a standard method would work as well. Additionally, the handler adds extra logic to only output end times and skips the start notification and the output nesting.

// Log to a memo to demonstrate custom logging ability
CustomLog log = delegate(bool isEnd, string taskName, 
		string category, TimeSpan elapsedTime)
{
    // Only log the End times where we have timings.
    if (isEnd)
    {
        txtCustomLog.AppendText(String.Format("{0}:{1} - End - ({2} msec)\r\n",
            category,
            taskName,
            elapsedTime.TotalMilliseconds));
    }
};

// Example using custom logging output
using (new SimpleTimer("Counting Sheep", null, log))
{
    int sheep = 0;
    for (int i = 0; i < 50000; i++)
    {
        sheep++;
    }
}

Some ideas on how this might be used:

1. Write the information to a file.
2. Write the information to a database.
3. Write the information to a custom logging solution in your application.
4. Keep some SimpleTimer calls in your production code and generate warnings or notifications when times exceed a predetermined threshold.

The addition of custom logging gives you more freedom to time, track, and respond as you see fit.

ASP.NET Web Service Note

SimpleTimer uses the Trace class for writing out the output. For Trace statements to work in an ASP.NET Web Service application, a change must be made to the Web.config file.

<?xml version="1.0"?>
<configuration>
  [...]
  <system.codedom>
    <compilers>
      <compiler language="c#;cs;csharp" 
                extension=".cs" 
                compilerOptions="/d:TRACE"

                type="Microsoft.CSharp.CSharpCodeProvider, System, 
		Version=2.0.3500.0, Culture=neutral, 
		PublicKeyToken=b77a5c561934e089" warningLevel="1" />
      </compilers>
  </system.codedom>
  [...]


</configuration>

The Web.config change can be made temporarily while doing the performance investigation and commented out when finished.

NOTE: Make sure to use the correct assembly version and PublicKeyToken for your version of .NET.

Conclusion

In the end, using SimpleTimer I discovered that I was wrong in my initial suspicion about which part of the process was slow. A completely different area of code was the problem. Once I knew what was slow, I more effectively used my limited time to improve the real problem area. I also ended up with a new triage tool to help me in the future.

Using a solution like SimpleTimer, doing code performance triage becomes pretty simple. You can drop the using statement around the code to test and easily remove it when done. You can also drop it throughout your application and not worry about the nesting calls as the indented output is very understandable.

History

• 22^nd October, 2009: Initial post
• 30^th October, 2009: Added section on Custom Logging; updated demo and source