A Debug Stopwatch

• Download source - 1.55 KB

The Problem

On occasions, one needs to take time samples of an operation but only as a diagnostic during development and/or testing in a debug build. And, while there is an excellent Stopwatch class in .NET 2.0, this class is inappropriate for non-diagnostic time sampling because it:

1. is not a static class, and
2. therefore does not support conditional debug builds.

The Solution

The solution is to wrap the Stopwatch class in a static class (called DebugStopwatch) that exposes the Stopwatch methods as wrapped in methods decorated with the ConditionalAttribute attribute. Also, because one would probably want to measure several intervals simultaneously, the DebugStopwatch class, being static (and therefore cannot be created as an instance) has to provide functionality to manage multiple instances of the .NET Stopwatch class. As an added feature, the DebugStopwatch class also allows one to accumulate multiple time samples. This might be useful to measure variances in a repetitive task.

The Implementation

The Sample Wrapper Class

This class is a simple wrapper for taking a time sample. We'll see how this class is used later. The sample name can be used to provide application specific information about the sample.

/// <summary>
/// A wrapper for a sample in time.
/// </summary>
public class Sample
{
  protected string sampleName;
  protected long milliseconds;

  /// <summary>
  /// Gets/sets milliseconds
  /// </summary>
  public long Milliseconds
  {
    get { return milliseconds; }
  }

  /// <summary>
  /// Returns sampleName
  /// </summary>
  public string SampleName
  {
    get { return sampleName; }
  }

  public Sample(string sampleName, long milliseconds)
  {
    this.sampleName = sampleName;
    this.milliseconds = milliseconds;
  }
}

The SampleDelta Wrapper Class

This class is a wrapper for the difference s[1]-s[0] and the total elapsed time s[1]. We'll see how this class is used later. The sample name can be used to provide application specific information about the sample.

/// <summary>
/// A wrapper for elapsed time between samples
/// and the total time from the first sample 
/// to the current sample.
/// </summary>
public class SampleDelta
{
  protected string sampleName;
  protected long milliseconds;
  protected long totalMilliseconds;

  /// <summary>
  /// Returns totalMilliseconds
  /// </summary>
  public long TotalMilliseconds
  {
    get { return totalMilliseconds; }
  }

  /// <summary>
  /// Returns milliseconds
  /// </summary>
  public long DeltaMilliseconds
  {
    get { return milliseconds; }
  }

  /// <summary>
  /// Returns sampleName
  /// </summary>
  public string SampleName
  {
    get { return sampleName; }
  }

  public SampleDelta(string sampleName, long milliseconds, long totalMilliseconds)
  {
    this.sampleName = sampleName;
    this.milliseconds = milliseconds;
    this.totalMilliseconds = totalMilliseconds;
  }
}

The DebugStopwatch Class

The Internal Collections

/// <summary>
/// Encapsulates methods that are executed only in Debug mode for measuring
/// timespans.
/// </summary>
public static class DebugStopwatch
{
  internal static Dictionary<Enum, Stopwatch> stopwatchMap = 
       new Dictionary<Enum, Stopwatch>();
  internal static Dictionary<Enum, List<Sample>> stopwatchSampleMap = 
       new Dictionary<Enum, List<Sample>>();

A dictionary is used to map between a stopwatch "descriptor" and the actual Stopwatch instance. A dictionary is also used to manage the samples for a particular stopwatch "descriptor". Note that the key in both dictionaries is an Enum, allowing you to "describe" your stopwatches using an enumeration rather than an integer ID or a string. Note that there are no conflicts between these two enumerations:

enum Modem
{
  Send=1,
  Receive=2,
}

enum DSL
{
  Send=1,
  Receive=2,
}

because the Enum types are different even if the enumeration value is the same. In other words, there will be two different entries in the dictionaries for Modem.Send and DSL.Send, even though the value for both of these enumerations is 1.

Regarding the internal keyword, I'm not exactly thrilled with the fact that C# does not allow protected members in a static class. The internal keyword prevents access to the members from a different assembly, but what I really want to do is to prevent access even from the same assembly. By marking the class as static, which is useful because it prevents someone from accidentally instantiating it, I lose what I consider to be important control over the visibility of my static class' members--they have to be public or internal.

Creating Entries in the Maps

An internal method creates an entry in both dictionaries if the stopwatch descriptor does not currently exist in the dictionaries. Note that the "value" member of the dictionary is initialized when the key is added to the dictionary.

/// <summary>
/// Creates, if new, the list entries for the stopwatch.
/// </summary>
/// <param name="t"></param>
internal static void CreateIfNotInMap(Enum t)
{
  if (!stopwatchMap.ContainsKey(t))
  {
    lock(stopwatchMap)
    {
      stopwatchMap[t] = new Stopwatch();
      stopwatchSampleMap[t] = new List<Sample>();
    }
  }
}

Why the lock? Because of the potential for different threads to be simultaneously adding to the dictionaries, and also because there might be a reader operation that is taking place while another thread is adding a stopwatch.

Basic Stopwatch Control

The basic stopwatch control consists of methods to start and stop the stopwatch and to start a new sample collection:

/// <summary>
/// Starts the specified stopwatch.
/// </summary>
[Conditional("DEBUG")]
public static void Start(Enum t)
{
  CreateIfNotInMap(t);
  stopwatchMap[t].Start();
}

/// <summary>
/// Resets the specified stopwatch, clears the samples,
/// and starts the stopwatch.
/// </summary>
/// <param name="t"></param>
[Conditional("DEBUG")]
public static void StartNew(Enum t)
{
  CreateIfNotInMap(t);
  stopwatchMap[t].Reset();
  stopwatchSampleMap[t].Clear();
  stopwatchMap[t].Start();
}

/// <summary>
/// Stops the specified stopwatch.
/// </summary>
[Conditional("DEBUG")]
public static void Stop(Enum t)
{
  stopwatchMap[t].Stop();
}

/// <summary>
/// Resets the specified stopwatch and clears the samples.
/// </summary>
[Conditional("DEBUG")]
public static void Reset(Enum t)
{
    stopwatchMap[t].Reset();
    stopwatchSampleMap[t].Clear();
}

The salient difference between StartNew and Reset is that Reset simply clears the sample collection and resets the stopwatch, whereas StartNew is a simpler way of calling Reset and Start in succession.

Why aren't there locks around the Clear calls above, in the StartNew and Reset methods? Because, these are methods that I consider to be "master control" methods. All threads that are doing sampling or reporting on samples should be suspended or terminated when these calls are made. Any other scenario doesn't make sense.

Taking a Time Sample

To take a time sample, call the Sample method for the desired stopwatch. The sampleName parameter is useful in providing some additional information about the time sample--the iteration count, for example.

/// <summary>
/// Saves the current elapsed time for the specified
/// stopwatch in the sample buffer.
/// </summary>
[Conditional("DEBUG")]
public static void Sample(Enum t, string sampleName)
{
  lock (stopwatchMap)
  {
    stopwatchSampleMap[t].Add(new Sample(sampleName, 
                   stopwatchMap[t].ElapsedMilliseconds));
  }
}

Why the lock? Because, these routines need to be thread safe, and it is possible that one thread might be adding to the stopwatch collection while another thread is getting the sample collection (see below).

Getting the Elapsed Time

At any time, whether the stopwatch is running or not, you can get the elapsed time by calling the ElapsedMilliseconds method.

/// <summary>
/// Gets the elapsed time in milliseconds for the specified stopwatch.
/// </summary>
/// <param name="t"></param>
[Conditional("DEBUG")]
public static void ElapsedMilliseconds(Enum t, ref long ret)
{
  ret = stopwatchMap[t].ElapsedMilliseconds;
}

And why, you ask, do I get the elapsed milliseconds using a ref parameter and not simply returning it? Because, conditional compilation requires that the method return type be void--in other words, it can't return anything. This is an inconvenience that sort of makes sense. If I could return the list, I would be able to write:

long ms=DebugStopwatch.ElapsedMilliseconds(Stopwatches.SW1);

And what would the compiler do if I compiled this in Release mode? By the way, the out keyword doesn't work either, because out initializes the variable, and if compiled in Release mode, the variable wouldn't be initialized, again giving the compiler fits, as it wouldn't be able to put out that useful error that a variable hasn't been initialized.

Get the Samples

At any time, the current collection of samples can be returned.

/// <summary>
/// Returns the sample buffer for the specified stopwatch.
/// The input list is replaced with a copy of the sample list at
/// the current moment in time.
/// </summary>
[Conditional("DEBUG")]
public static void GetSamples(Enum t, ref List<Sample> ret)
{
  lock (stopwatchMap)
  {
    ret = new List<Sample>(stopwatchSampleMap[t]);
  }
}

As stated above, conditional compilation methods cannot return anything, so the return must be handled by a ref. The lock prevents the sample list from being updated while we copy it, and we copy it so that the caller gets a copy, not the original. This keeps us safe from the caller tampering with our list, and the caller doesn't have to worry about threading--the copy is the caller's own to do with as it pleases.

Get the Sample Deltas

At any time, you can get the list of samples as time deltas.

/// <summary>
/// Returns the buffer of sample deltas, S(n) - S(n-1) for the specified stopwatch.
/// The input list is replaced with the sample delta list.
/// </summary>
[Conditional("DEBUG")]
public static void GetSampleDeltas(Enum t, ref List<SampleDelta> ret)
{
  List<Sample> samples = null;
  GetSamples(t, ref samples);
  ret = new List<SampleDelta>();

  if (samples.Count > 0)
  {
    Sample s0=samples[0];
    ret.Add(new SampleDelta(s0.SampleName, s0.Milliseconds, s0.Milliseconds));
    long ms=s0.Milliseconds;

    for (int i=1; i<samples.Count; i++)
    {
      Sample sn=samples[i];
      long delta = sn.Milliseconds - ms;
      ret.Add(new SampleDelta(sn.SampleName, delta, sn.Milliseconds));
      ms=sn.Milliseconds;
    }
  }
}

This is a nice helper method to get the time between each sample, rather than having to write this method yourself. A running total is also kept.

Doing a Sample Dump

A helper method called DumpSamples does a debug output of all the samples currently in the collection for the specified stopwatch. If you are using Traceract, the output would look similar to this (taken from the unit tests):

A Note About Exceptions

This class does not explicitly test whether the stopwatch descriptor exists in the dictionary. The dictionary is already doing this test, and if the descriptor doesn't exist in the dictionary, you will get an exception from the dictionary rather than the stopwatch class.

Unit Tests

There are three unit tests that validate the basic functionality of the DebugStopwatch class and verify that enumerations of different types are truly different even if their values are the same. These tests rely on the sequencing capability of my unit test application.

Given:

public class DebugStopwatchTests
{
  protected enum Items1
  {
    Avi,
    Mpg,
  }

  protected enum Items2
  {
    Dvd,
  }

  protected int[] delays = new int[] { 100, 200, 300 };
  protected string[] sampleNames1 = new string[] { "A1", "A2", "A3" };
  protected string[] sampleNames2 = new string[] { "D1", "D2", "D3" };
  protected string[] sampleNames3 = new string[] { "M1", "M2", "M3" };

The first unit test verifies the samples and their deltas:

/// <summary>
/// Tests managing samples for a single enum type.
/// </summary>
[Test, Sequence(0)]
public void SampleTest1()
{
  DebugStopwatch.Start(Items1.Avi);

  for (int i = 0; i < 3; i++)
  {
    Thread.Sleep(delays[i]);
    DebugStopwatch.Sample(Items1.Avi, sampleNames1[i]);
  }

  List<SampleDelta> samples = null;
  DebugStopwatch.GetSampleDeltas(Items1.Avi, ref samples);
  Assertion.Assert(samples.Count == 3, "Expected 3 samples.");

  for (int i = 0; i < 3; i++)
  {
    Assertion.Assert(InRange(samples[i].DeltaMilliseconds, delays[i]), 
      "Sample not within expected range.");
    Assertion.Assert(samples[i].SampleName == sampleNames1[i], 
      "Sample name does not match.");
  }
}

The second unit test verifies that samples taken for Items2.Dvd (value 0) are different from the samples taken for Items1.Avi (also value 0):

/// <summary>
/// Tests that there is not conflict between
/// the previous sample enum and a different one,
/// even though the enumerations begin at the same values.
/// </summary>
[Test, Sequence(1)]
public void SampleTest2()
{
  DebugStopwatch.Start(Items2.Dvd);

  for (int i = 0; i < 3; i++)
  {
    Thread.Sleep(delays[i]);
    DebugStopwatch.Sample(Items2.Dvd, sampleNames2[i]);
  }

  List<SampleDelta> samples = null;
  DebugStopwatch.GetSampleDeltas(Items2.Dvd, ref samples);
  Assertion.Assert(samples.Count == 3, "Expected 3 samples.");

  for (int i = 0; i < 3; i++)
  {
    Assertion.Assert(InRange(samples[i].DeltaMilliseconds, delays[i]), 
       "Sample not within expected range.");
    Assertion.Assert(samples[i].SampleName == sampleNames2[i], 
       "Sample name does not match.");
  }
}

And, the last unit test verifies that Items1.Mpg (value 1) creates a different sample list from Items.Avi (value 0):

/// <summary>
/// Tests that there is not conflict between
/// the first sample enum and a second enumeration value.
/// </summary>
[Test, Sequence(3)]
public void SampleTest3()
{
  DebugStopwatch.Start(Items1.Mpg);

  for (int i = 0; i < 3; i++)
  {
    Thread.Sleep(delays[i]);
    DebugStopwatch.Sample(Items1.Mpg, sampleNames3[i]);
  }

  List<SampleDelta> samples = null;
  DebugStopwatch.GetSampleDeltas(Items1.Mpg, ref samples);
  Assertion.Assert(samples.Count == 3, "Expected 3 samples.");

  for (int i = 0; i < 3; i++)
  {
    Assertion.Assert(InRange(samples[i].DeltaMilliseconds, delays[i]), 
       "Sample not within expected range.");
    Assertion.Assert(samples[i].SampleName == sampleNames3[i], 
       "Sample name does not match.");
  }

  DebugStopwatch.DumpSamples(Items1.Mpg);
}

Conclusion

Hopefully, you will find this class useful for adding debug build time sampling, and you won't find it too annoying that you have to use a ref variable to return the elapsed time and time samples.