So every now and then you find things that you wish you’d found many years ago. For me, one of those things is the System.Diagnostics.Stopwatch. It is propably one of the simplest objects you can think of, but it saves you a lot of time.

It does what you’d expect: it measures time. And you no longer have to write code to measure time yourself.

In this post I’ll give an example of using the stopwatch to measure the time that it takes to run a heavy method. The fact that the stopwatch knows about that time doesn’t help you: you’ll have to output that time in such a way that you can read it. And you want to be able to do that in a released version of your app, not in – not compiler optimized – debug mode. That’s where Tracing comes in.

The Stopwatch and Tracing are demonstrated in a simple Console Application.

Let’s look at the code!


using System;
using System.Collections.Generic;
using System.Linq;
using System.Text;
using System.Threading.Tasks;
using System.Diagnostics;
using System.IO;

namespace ReadySetGo
{
    class Program
    {
        static void Main(string[] args)
        {
            // Instantiate a stopwatch
            Stopwatch sw = new Stopwatch();

            // Init the tracing
            // Output to the system tempfolder
            String fileLocation = Path.Combine(Path.GetTempPath(), "MyTraceFile.txt");
            Stream outputFile = File.Create(fileLocation);

            // Setup the tracing
            TextWriterTraceListener textListener = new TextWriterTraceListener(outputFile);
            TraceSource traceSource = new TraceSource("Stopwatch Trace", SourceLevels.All);

            traceSource.Listeners.Clear(); // remove the default ConsoleTraceListener
            traceSource.Listeners.Add(textListener); // add our textlistener

            sw.Start(); // start the stopwatch

            traceSource.TraceEvent(TraceEventType.Verbose, 100, "Invoking DoSomeHeavyWork");
            DoSomeHeavyWork();

            sw.Stop();// stop the stopwatch

            Console.WriteLine("Tracefile written to {0}", fileLocation);

            if (sw.ElapsedMilliseconds > 1000)
            {
                traceSource.TraceEvent(TraceEventType.Warning, 100, "DoSomeHeavyWork took {0} miliseconds", sw.ElapsedMilliseconds.ToString());
            }
            else
            {
                traceSource.TraceEvent(TraceEventType.Verbose, 100, "DoSomeHeavyWork took {0} miliseconds", sw.ElapsedMilliseconds.ToString());
            }
            
            // finish up the traceSource
            traceSource.Flush();
            traceSource.Close();

            // for your convenience: show the tracefile in your default editor
            Process.Start(fileLocation);

            Console.WriteLine("Press a key to exit");
            Console.Read();

        }

        static void DoSomeHeavyWork()
        {
            List lst = new List();
            
            for (int i = 0; i <= 20000; i++)
            {
                if (!lst.Contains(i.ToString())){
                    lst.Add(i.ToString());
                }
            }
        }
    }
}

Let’s analyze this.

First, at line 6 we import the System.Diagnostics. The Stopwatch and Trace functionality are part of it, and so is the Process at line 54.

At line system you find System.IO. Needed because we need a Filestream, and because we use Path to get the default system’s tempdirectory.

Line 17 instantiates a Stopwatch. Easy as pressing a button..

At line 21-22 a stream is created, pointing at a file in the system’s temp directory. This is the file that will contain all tracing information.

Line 25 creates a TextWriterTraceListener. When doing traces, you fire an event at the moment you want to register/trace information. This event can be handled by multiple listeners. In this example we use the TextWriterTraceListener. Everytime an event is fired by the TraceSource, the TextWriterTraceListener catches that and writes the text to the file from the stream we created at line 21. Uhm.. TraceSource?

Line 26 creates the TraceSource. This is the object that will fire the tracing events that are writen to file by the TextWriterTraceListener. We give it the name “Stopwatch Trace”, and tell it to handle all possible trace events.

At line 28 we remove all listeners that are attached to the traceSource. We didn’t add one explicitly, however, when generating a new TraceSource, a default listener is added automatically (one that outputs the trace to the console). We don’t want that, so we remove it. Next, at line 29 we add our TextWriterTraceListener to the TraceSource.

Line 31 starts the stopwatch.

Line 33 tells the TraceSource to fire an event. The type is Verbose. You have multile types, like Critical, Error, Warnig, etc. In this case we just want to tell something, so we make it “verbose”.

You will see the number 100. This is an integer that could have any integer value. the traceSource doesn’t really use it. It only prints this number in your trace file. If you trace multiple processes, you can number those processes. E.g. all calls to webservices get the number 1000, all database transactions get the number 2000, etc. This is just for you, as reference.

Next, at line 34, we invoke a method that takes some time. The method itself contains just some code that consumes time, no other prupose. In real life, this could be a method that does some heavy database queries, or other calculations.

Line 36 stops the stopwatch, after the method has finished.

To read the stopwatch, we use the property ElapsedMilliSeconds.

If the method took more than 1000 milliseconds, the sourceTrace will fire a new event, this time as warning.

If less that 1000 milliseconds, the event will be of type “verbose”.

Note that you can use string formatting in the message (the {} substitutes).

Finally, line 50 and 51 finish the traceSource. This is important, for the traceSource uses a file stream.

Finally, at line 54, the System.Diagnostics.Process.Start method is used to show the trace file, so you do not have to find it in your temp folder yourself.

Run the code, and see what happens. This gives you a tool to find bottlenecks in your code!

Some last remarks.

The tracing is a system that fires events, handels events, and in this case even writes to a file. Note that those things come with performance loss. It’s minimal, but the more you trace, the more resources it’ll take.

If you want to use tracing in a live-application, make sure you build in a way to switch on and off the tracing, e.g. by setting a boolean.