Click here to Skip to main content
Click here to Skip to main content

Measure time with LogTimer

, 4 May 2012 CPOL
Rate this:
Please Sign up or sign in to vote.
How to measure time and find bottleneck points of an application with LogTimer

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

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)

Share

About the Author

panboza
Software Developer
Israel Israel

I have been developing professionally since 2002.

 

I developed desktop applications in C++ and C#. Now developing web applications and sites in PHP.

 


 
Visit Panboza.

Comments and Discussions

 
GeneralMy vote of 3 PinmemberJoe Sonderegger7-May-12 21:14 
GeneralThe Console.WriteLine is for demonstration only ;) Pinmemberzebrot8-May-12 0:29 
QuestionDateTime.Now precision PinmemberJcmorin7-May-12 6:22 
AnswerRe: DateTime.Now precision Pinmemberzebrot8-May-12 0:21 
I did not notice this precision problem since I did not measure times in those ranges.
 
I will update the class and rely on Environment.TickCount property for better precision.
SuggestionRe: DateTime.Now precision PinmemberJcmorin8-May-12 2:40 
QuestionI'm confused Pinmemberhvasilev6-Mar-12 7:55 
AnswerThe Differences : Pinmemberzebrot6-Mar-12 20:42 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.

| Advertise | Privacy | Terms of Use | Mobile
Web02 | 2.8.141223.1 | Last Updated 4 May 2012
Article Copyright 2012 by panboza
Everything else Copyright © CodeProject, 1999-2014
Layout: fixed | fluid