Introduction

Sometimes we need to know the elapsed time of a method call, that is, how long its taking the code to get run. Usually we suspect the code segment is taking to long to execute and we need to find the bottleneck or maybe we are developing an application with some time restrictions.

There are several functions on the kernel32.dll windows library that may help in this task. GetTickCount (and GetTickCount64) and the combination of QueryPerformanceCounter and QueryPerformanceFrecuency.

Getting the elapsed time between to instants

Using GetTickCount

procedure MiMeasurableProcedure;
var
  startTime, endTime,elapsedTime : integer;
  data1, data2 : integer;
begin
  // We're not interested in this
  CalculateOne;
  CalculateTwo;
  // Here we start the measurement
  startTime := GetTickCount;
  CalculateThree(data1);
  CalculateFour(data2);
  result := VeryComplexOperation(data1+ data2);
  // Here we stop the measure
  endTime := GetTickCount;
  // And here we show the elapsed time
  elapsedTime := endTime - startTime;
  ShowMessage('Operation took ' + IntToStr(elapsedTime) + 'ms');
end;

Using GetTick count involves just invoking the function before and after the piece of code that we want to measure and the actual time spent, in milliseconds, whould be the substraction between the start time and the end time.

Using QueryPerformanceCounter

It’s a very similar process

procedure MiMeasurableProcedure;
var
  startTime, endTime, monitorFrecuency : int64;
  elapsedTime : double;
  data1, data2: integer;
begin
  // Obtener la frecuencia del monitor
  QueryPerformanceFrequency(monitorFrecuency);
  // Hacer cosas que no queremos medir
  CalculateOne;
  CalculateTwo;
  // Here we start the measurement
  QueryPerformanceCounter(startTime);
  CalculateThree(data1);
  CalculateFour(data2);
  result := VeryComplexOperation(data1+ data2);
  // Hasta aqui
  QueryPerformanceCounter(endTime);
  { Show the elapsed time.
     monitorFrecuency has the number of 'ticks' per second the monitor is using }
  elapsedTime := (endTime - startTime) / monitorFrecuency ;
  ShowMessage('Operation took ' + FloatToStr(elapsedTime) + 's');
end;

QueryPerformanceCounter in C#

Note: This is here just for information purposes. While you can use the performance counters on C#, the recomended way of measuring execution time

In C# (at least in C# 2.0) the QueryPerformance functions are not included so, before we can access them we need to import them from the kernel32.dll. In order to do so we need to include the following code:

[DllImport("Kernel32.dll")]
        private static extern bool QueryPerformanceCounter(
            out long lpPerformanceCount);

[DllImport("Kernel32.dll")]
        private static extern bool QueryPerformanceFrequency(
            out long lpFrequency);

If you want you may even create an static class wrapping the calls to this functions in order to avoid having to import the functions for every unit we plan to use them.

GetTickCount vs GetTickCount64 vs QueryPerformanceCounter

The main difference between any of the GetTickCount and the QueryPerformanceCounter is the precision of the measure. GetTickCount returns the number of elapsed milliseconds since the system was started and has a precision of about a millisecond (although it’s not guaranteed and can be different), that is, if we make a call to GetTickcount and 500 microseconds later we make another one, both of the calls will return the same result.

QueryPerformancecounter on the other hand looks up the current value of the high resolution monitor of the system (provided there’s one as is hardware based, although nowadays every computer has one). It has a much higher resolution (about one nanosecond).

Lastly the difference between GetTickCount and GetTickCount64 is the return type. GetTickCount return 32 bits integer which makes the maximum “distance” between two call as long as 49,7 days, that is, if we assume when we start the system the tick count is 0, 49,7 days after that the system tick count will be 0 again. GetTickCount64 uses a 64 bits integer which provides with a much more wide spectrum.

Stopwatch class

From the version 2.0 of the .NET framework a new class exists, the Stopwatch class in the System.Diagnostics namespace, which provide us with the functionality to measure the elapsed time between to sections of the code.

The thing about the stopwatch class is that it provides you with almost everything you may need, specifically if a high resolution performance counter exists the class will automatically used it, so you’ll get a high precision.

Stopwatch stopWatch = new Stopwatch();
stopWatch.Start();
// Do some work
DoWork();
stopWatch.Stop();
// Get the elapsed time as a TimeSpan value.
TimeSpan ts = stopWatch.Elapsed;

IDisposable Stopwatch

A handy trick to make the measurment of code easier with a stopwatch while keeping the code elegant is to build on top of the handy characteristics of the IDisposable interface and the using directive.

In C#, the language enables the use of the using directive in order to automatically invoke the dispose method on a class that implements the IDisposable interface. Therefore the compiler will automatically convert this:

using (new MyDisposableClass())
{
  // Do something
}

into

var c = new MyDisposableClass();
// Do something
c.Dispose();

We can take advantae of that quality and create a Profiler class like:

public class Profiler : IDisposable
{
  event Action<TimeSpan> OnFinish;
  Stopwatch watch = new Stopwatch();

  public static Profiler Start(Action<TimeSpan> finishHandler)
  {
    return new Profiler(finishHandler);
  }

  private Profiler(Action<TimeSpan> finishHandler)
  {
    OnFinish += finishHandler;
    watch.Start();
  }

  public void Dispose()
  {
    watch.Stop();
    if (OnFinish != null)
      OnFinish(watch.Elapsed);
    }
}

The class defines a private constructor so that it can only be invoked with the Start (signifying clearly that it does start the profiler) and it uses the disposable interface to implement the stoping of the stop watch and then invoke the callback provided in the initialization. We can then use it like this:

using (Profiler.Start(p => Console.WriteLine("Execution time: {0} ms", p.TotalMilliseconds)))
{
  // Code to measure goes here
}

Leave a Reply