Measure time with LogTimer

• Download demo project - 10.8 Kb

Introduction

In my last project, I needed to check what slows my application. To identify the bottleneck points of the misbehaved application I needed to measure the execution's times of several code blocks.

While System.Diagnostics.StopWatch is the obvious solution to this problem, it lacks some features I wanted:

• Measuring samples - sample is the interval between Start() and its sequential Stop().
• Retrieving the duration of the last sample - While System.Diagnostics.StopWatch allows to measure the duration of all samples (the duration of all Start and Stop intervals) you can not retrieve the duration of the last sample (the last Start and its sequential Stop interval).
• Retrieving the total execution's time - The total execution's time may have one of the following meanings:
  • The time passed since the first Start() and the last Stop()
  • The time passed since the first Start() and the current time
• Retrieving the percent of measured time of sampels from total execution's time
• Retrieving the number of samples(Start and Stop intervals) and query the average of execution time of a sample.

The Demo Program

The demo program demonstrate how to use LogTimer. We will measure the execution's time of DoSomeWork(int timeout) which simply sleep for timeout milliseconds. The timer data will be displayed on the console after each step, the time is displayed as number of milliseconds.

public class LogTimerDemo {
  //-------------------------------------------------------------------------
  public static void Main(string[] args) {
    LogTimerDemo demo = new LogTimerDemo();
    LogTimer timer = new LogTimer();

    demo.Display(timer,"0");
    //-----------------------------------------------------------------------
    // Stage 1 : Let measure the exectution time of DoSomeWork(2000)
    timer.Start(); demo.DoSomeWork(2000); timer.Stop();
    demo.Display(timer,"1");
    //-----------------------------------------------------------------------
    // Stage 2 - Let wait 3 seconds. Note the influence of AllFromNow property
    Thread.Sleep(3000);
    timer.AllFromNow = false; demo.Display(timer,"2");
    timer.AllFromNow = true;  demo.Display(timer,"3");
    //-----------------------------------------------------------------------
    // Stage 4 : Let measure the exectution time of DoSomeWork(5000)
    timer.Start(); demo.DoSomeWork(5000); timer.Stop();
    demo.Display(timer,"4");
    //-----------------------------------------------------------------------
    // Stage 4 : Let measure the exectution's time of calling DoSomeWork(100)
    // 100 times in sequence and check the average time DoSomeWork(100). Note
    // that we use AddSample() that is more accurate than calling Stop() and
    // Start() in sequence.
    timer.Reset();
    for (int ii = 0;ii > 100;ii++) {
      timer.AddSample();
      demo.DoSomeWork(100);
    }
    timer.Stop();
    demo.Display(timer,"5");
    //-----------------------------------------------------------------------
  }
  //-------------------------------------------------------------------------
  public void DoSomeWork(int ms) {
    Thread.Sleep(ms);
  }
  //-------------------------------------------------------------------------
  public void Display(LogTimer timer,string perfix) {
    System.Console.WriteLine("{6} => All: {0:D5} , Value: {1:D5} , Current: {2:D5}, Stats: {3,3}%, Average ; {4:D5} [{5} samples]",timer.All.Ms(),timer.Value.Ms(),timer.Current.Ms(),timer.PercentAll,timer.Average.Ms(),timer.Count,perfix);
  }
  //-------------------------------------------------------------------------
}

Here the program output on my machine:

Using LogTimer

• You can start a new sample (start to measure time) by calling Start().You can also start the timer immediately while creating a new timer by invoking the constructor with true. While calling Start() when the timer is running(measuring time) is allowed, it will be ignored by the timer.
• You can end sample (stop measuring time) by calling Stop(). The return value of this is last sample's time (the time measured since last valid Start()). This sample's time is also added to total measured time. After the timer has stopped you can call Start() to measure other event in later time. While calling Stop() when the timer is not running(measuring time) is allowed, it will be ignored by the timer.
• You can add a new sample by callling AddSample. This is the same effect of calling Stop() and Start in sequence but it is more accurate.
• You can reset the timer by Calling Reset(). You can also start the timer immediately if called with true or by calling Restart().
• You can use Value property to retrieve the total measured time (All samples' times). If the property invoked while the timer is running, the value will be the measured time at the property invocation.
• You can use Current property to retrieve the time of the last sample (The interval between last Start()and Stop()). If the property invoked while the timer is running, the value will be the measured time at the property invocation.
• You can use All property to retrieve the total execution's time. the actual meaning of this measurement depends on the value of AllFromNow property. If the property is true the value will be the time the time passed since the first call to Start() after last Reset() and the current time, Otherwise the value will be the time passed since the first call to Start() after last Reset() and last call to Stop(). If the property invoked while the timer is running, the value will be the measured time at the property invocation.
• You can use Count property to retrieve the number of Start() and Stop() intervals. The Average property is average duration of the interval. (Value/Count)

History

• Version 3 - Add AllFromNow and Restart
• Version 2 - Explain the differances between System.Diagnostics.StopWatch and LogTimer.
• Version 1