Click here to Skip to main content
15,868,070 members
Articles / Programming Languages / C#

Quick Performance Triage

Rate me:
Please Sign up or sign in to vote.
4.85/5 (14 votes)
3 Nov 2009CPOL6 min read 33.3K   202   33   14
Class to help triage performance problems in your application

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

C#
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

C#
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.

C#
//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.

C#
// 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
<?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

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

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)


Written By
Technical Lead
United States United States
Mark Ericksen is a Senior Developer, Technical Lead, Architect and more. He is passionate about technology, photography, and continually learning.

Comments and Discussions

 
GeneralSuggestions Pin
N a v a n e e t h30-Oct-09 19:06
N a v a n e e t h30-Oct-09 19:06 
AnswerRe: Suggestions Pin
Mark Ericksen2-Nov-09 6:29
Mark Ericksen2-Nov-09 6:29 
NewsUpdated code and article Pin
Mark Ericksen30-Oct-09 12:57
Mark Ericksen30-Oct-09 12:57 
The article was updated adding the "Custom Logging" section. The code and the demo project were both updated to allow for custom logging solutions. The article text shows how this works and offers suggestions on applications. This follows a suggestion from Andrew Rissing. Thanks Andrew!

Enjoy!
-Mark Ericksen
NewsUpdated attached zip files - small correction Pin
Mark Ericksen22-Oct-09 5:19
Mark Ericksen22-Oct-09 5:19 
GeneralThe code... Pin
Andrew Rissing22-Oct-09 4:56
Andrew Rissing22-Oct-09 4:56 
GeneralRe: The code... Pin
Mark Ericksen22-Oct-09 5:04
Mark Ericksen22-Oct-09 5:04 
GeneralRe: The code... Pin
Andrew Rissing22-Oct-09 7:28
Andrew Rissing22-Oct-09 7:28 
GeneralRe: The code... Pin
Mark Ericksen22-Oct-09 9:16
Mark Ericksen22-Oct-09 9:16 
GeneralRe: The code... Pin
Mark Ericksen30-Oct-09 13:02
Mark Ericksen30-Oct-09 13:02 
GeneralElegant + Simple == 5 Pin
Humble Programmer22-Oct-09 3:27
Humble Programmer22-Oct-09 3:27 
GeneralRe: Elegant + Simple == 5 Pin
Mark Ericksen22-Oct-09 4:14
Mark Ericksen22-Oct-09 4:14 
QuestionIs this not a job for RedGate ANTS Profiler? Pin
George Belletty21-Oct-09 22:03
George Belletty21-Oct-09 22:03 
AnswerRe: Is this not a job for RedGate ANTS Profiler? Pin
Mark Ericksen22-Oct-09 2:19
Mark Ericksen22-Oct-09 2:19 
GeneralRe: Is this not a job for RedGate ANTS Profiler? Pin
George Belletty22-Oct-09 5:21
George Belletty22-Oct-09 5:21 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.