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:
- 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.
- 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)))
{
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.
{
}
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.
CustomLog log = delegate(bool isEnd, string taskName,
string category, TimeSpan elapsedTime)
{
if (isEnd)
{
txtCustomLog.AppendText(String.Format("{0}:{1} - End - ({2} msec)\r\n",
category,
taskName,
elapsedTime.TotalMilliseconds));
}
};
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:
- Write the information to a file.
- Write the information to a database.
- Write the information to a custom logging solution in your application.
- 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.
="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
Mark Ericksen is a Senior Developer, Technical Lead, Architect and more. He is passionate about technology, photography, and continually learning.