It is often helpful to track the timing of sections of code. One way to accomplish this is to put messages directly into your code that displays the timings.
DISCLAIMER: this article is not about performance tuning of code, it is about simplifying incorporating timing during development.
Let’s take a look at a method that given an integer, returns the sum of all integers up to the passed integer, and has code to display timings.
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 |
// returns the sum of all integers up to an integer public int SumUpTo(int upTo) { var result = 0; var startTime = DateTime.UtcNow; TimeSpan elapsed; Console.WriteLine($"SumUpTo started at { startTime: yyyy-MM-dd HH:mm:ss.fff} UTC"); for (int i = 0; i <= upTo; i++) { result+=i; // interim message – every 100,000 show elapsed if (i % 100000 == 0) { elapsed=DateTime.UtcNow.Subtract(startTime); Console.WriteLine($"SumUpTo – i = {i} {elapsed.TotalMilliseconds}ms"); } } elapsed = DateTime.UtcNow.Subtract(startTime); Console.WriteLine($"SumUpTo took { elapsed.TotalMilliseconds}ms"); return result; } |
If you call this method and pass 1,000,000 you will see output similar to the following:
SumUpTo started at 2019-12-22 20:51:02.420 UTC
SumUpTo – i = 0 0ms
…
SumUpTo – i = 1000000 6.9798ms
SumUpTo finished 6.9798ms
While helpful in determining where timing issues lie in the code, it has side effects:
- It adds several lines of code that have nothing to do with the behavior of the method – there are ten lines of code that do not relate to the calculation of the return value, which will impact timing. It may not be a significant impact, but there is an impact. The less we do, the less impact on timing we will experience.
- These extra lines of code are spread throughout the routine:
- a start time is captured at the beginning
- an elapsed time is calculated at several places
- a periodic status message every 100,000 iterations of the loop
- a summary message at the end, showing the elapsed time.
- Capturing elapsed time has accuracy and thread safety issues. – there is a class in the .NET framework called Stopwatch that can help with this, we’ll see in a later part of this series.
- Removing the timing code can be tedious.
One approach I have used to make this cleaner and to address these issues is to simply wrap what I want to measure with a “using” statement that instantiates an instance of a class called WatchMe. Here is the same method, re-written using the WatchMe class:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
public int SumUpTo(int upTo) { using (var sw = new WatchMe("SumUpTo")) { var result = 0; for (int i = 0; i <= upTo; i++) { result += i; // interim message – every 100,000 show elapsed if (i % 100000 == 0) { sw.ShowMessage($"i = {i}"); } } return result; } } |
Much cleaner, in fact if we take out the “if” statement surrounding the call to ShowMessage, the using takes care of all of the timings.
The WatchMe class takes care of the following:
- Takes advantage of the IDisposable interface to capture finish elapsed time, and logging the final elapsed time message.
- Uses the Stopwatch class to handle some of the issues with capturing elapsed time.
- Holds on to the title of what is being watched (e.g. SumUpTo)
- Captures the DateTime start variable used later to calculate the various elapsed times.
- Automatically displays the start and finished messages
- Simplifies the interim message to only the message: the title and elapsed times are added to the message automatically.
We’ll take a look at the WatchMe class in part 2 of this series.