Introducción

En determinadas ocasiones necesitamos saber el tiempo que tarda una determinada rutina en ejecutar generalmente por que creemos que un determinado fragmento esta tardando más de lo esperado y queremos saber donde está el cuello de botella o por que tenemos alguna aplicación que tiene establecidos unas limitaciones de rendimiento que queremos cumplir.

Hay varias funciones en el la libreria kernel32.dll de windows que pueden ayudarnos en nuestra tarea. GetTickCount (y GetTickCount64) y la combinación de QueryPerformanceCounter y QueryPerformanceFrecuency.

Obteniendo el tiempo transcurrido entre dos instantes

Usando GetTickCount

procedure MiProcedureAMedir;
var
  startTime, endTime,elapsedTime : integer;
  dato1, dato2 : integer;
begin
  // Hacer cosas que no queremos medir
  CalculaUno;
  CaculaDos;
  // Queremos medir desde aquí
  startTime := GetTickCount;
  CalculaTres(dato1);
  CalculaCuatro(dato2);
  result := OperaciónMuyCompleja(dato1 + dato2);
  // Hasta aqui
  endTime := GetTickCount;
  // Mostrar el tiempo transcurrido
  elapsedTime := endTime - startTime;
  ShowMessage('La operación tardó ' + IntToStr(elapsedTime) + 'ms');
end;

Usando QueryPerformanceCounter

El proceso es muy similar al método anterior

procedure MiProcedureAMedir;
var
  startTime, endTime, monitorFrecuency : int64;
  elapsedTime : double;
  dato1, dato2 : integer;
begin
  // Obtener la frecuencia del monitor
  QueryPerformanceFrequency(monitorFrecuency);
  // Hacer cosas que no queremos medir
  CalculaUno;
  CaculaDos;
  // Queremos medir desde aquí
  QueryPerformanceCounter(startTime);
  CalculaTres(dato1);
  CalculaCuatro(dato2);
  result := OperaciónMuyCompleja(dato1 + dato2);
  // Hasta aqui
  QueryPerformanceCounter(endTime);
  { Mostrar el tiempo transcurrido.
     monitorFrecuency tiene el numero de 'ticks' por segundo que da el monitor }
  elapsedTime := (endTime - startTime) / monitorFrecuency ;
  ShowMessage('La operación tardó ' + FloatToStr(elapsedTime) + 's');
end;

QueryPerformanceCounter en C

En C# (al menos en Visual Studio 2005) las funciones no estan incluidas en ninguna biblioteca por defecto por lo que, antes de poder usarlas, deberemos importarlas de la librería kernel.dll, para ello, en la clase en que las vayamos a utilizar debemos incluir las siguientes lineas.

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

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

No es mala idea crear una clase estática que encapsule las llamadas a estas funciones para no tener que incluir esas lineas en todas las clases en las que queramos usarlas.

GetTickCount vs GetTickCount64 vs QueryPerformanceCounter

La principal diferencia entre cualquiera de los GetTickCount y la función QueryPerformanceCounter es la precisión de la medida realizada. GetTickCount nos devuelve el numero de milisegundos transcurridos desde que se arrancó el sistema y tiene una precisión del orden del milisegundo (aunque puede ser mayor que un milisegundo), es decir, si hacemos una llamada a GetTickCount y 500 microsegundos despues hacemos otra llamada a GetTickCount ambas llamadas nos devolverán exactamente lo mismo.

La función QueryPerformanceCounter toma el valor actual del monitor de alta resolución del sistema (hardware). Tiene una resolución muchisimo más alta (del orden del nanosegundo) pero para que pueda funcionar obviamente el hardware tiene que tener un monitor de alta resolución (aunque prácticamente todos procesadores en la actualidad lo tienen).

Por último la diferencia entre GetTickCount y GetTickCount64 es, como indica el nombre, el tipo devuelto. La función GetTickCount devuelve enteros de 32 bits por lo que la máxima distancia entre dos llamadas es de 49,7 dias, es decir, si contamos con que en el momento de arranque del sistema el número de ‘ticks’ es cero, 49,7 días después dicho valor volverá a ser cero. ¿Que significa esto? Significa que corremos el riesgo de que entre dos llamadas a la función GetTickCount se produzca un reseteo de forma que cuando calculemos el numero de milisegundos transcurridos entre ambas medidas obtendremos un valor erroneo.

Stopwatch class

Desde la versión 2.0 del framework de .NET existe una nueva clase, la clase Stopwatch en el namespace System.Diagnostics, que nos proporciona la funcionalidad precisamente para medir el tiempo transcurrido entre dos secciones de código.

Una de las cosas de la clase stopwatch es que nos provee de prácticamente cualquier cosa que necesitamos, especificamente que si existe un monitor de alta resolución (performance counter) la clase lo usuará de forma automática para obtener una precisión mayor.

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

Un buen truco para hacer que la medición sea más sencilla y más elegante mediante un stopwatch es hacer uso de las características del interfaz IDisposable y la directiva using en C#

En C#, el lenguaje permite el uso de la directiva using para invocar de forma automática el metodo dispose en una clase que implemente el interfaz IDisposable cuando alcanzamos el final del bloque using. De esta forma, el compilador convertirá automáticamente esto:

using (new MyDisposableClass())
{
  // Ejecutar algún código
}

en

var c = new MyDisposableClass();
// Ejecutar algún código
c.Dispose();

Podemos sacar partido de esa propiedad e implementar nuestro monitor de rendimiento como:

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);
    }
}

La clase, que define un constructor privado de forma que solo pueda ser invocada con el metodo Start (indicando claramente que se está arrancando la medición), usa la implementación del interfaz IDisposable para implementar la parte final de la medición, es decir, prar el stopwatch e invocar el callback proporcionado como parte el método Start. De esta forma podríamos usarlo asi:

using (Profiler.Start(p => Console.WriteLine("Execution time: {0} ms", p.TotalMilliseconds)))
{
  // Código a medir
}