Medir el tiempo de una rutina

¿Alguna vez se preocupó por la velocidad con la que corre su programa? ¿No? Entonces usted es un candidato perfecto para jugar al Java. En caso contrario, voy a explicarle un pequeño código que utilizaremos en próximas entregas para medir el tiempo de ejecución de determinadas rutinas.

Ya lo dijo alguien: "La optimización prematura es la raíz de todos los males". No hay nada más cierto, aunque también es verdad que hacer algo simple de la peor forma posible, es la causa de otros grandes males. Con esto quiero decir que debería intentar hacer las cosas de la forma más simple y más óptima que usted conozca (dándole mayor importancia a la simplicidad del código); luego se preocupa por "darle velocidad" a la rutina que provoca el cuello de botella (en próximos posts veremos cómo usar gprof para detectarlo).

La forma de calcular el tiempo de CPU que toma una función es muy simple:
  • tomamos el valor del reloj antes de realizar la llamada (t_ini),
  • llamamos a la rutina en cuestión, y
  • tomamos nuevamente el valor del reloj (t_fin).
La diferencia entre t_fin - t_ini nos da el total de tiempo que tomó: 1) hacer la llamada a la rutina, 2) que esta haga su trabajo, 3) que devuelva el resultado.

Ahora hay algunos pequeños detalles de implementación. Por ejemplo, ¿qué función usar para tomar el tiempo del reloj? Y más importante, ¿qué precisión obtenemos con dicha función?

Para tomar el tiempo podemos usar la rutina clock(), que devuelve el tiempo aproximado de CPU que transcurrió desde que nuestro programa fue iniciado, dicho tiempo representado en un valor de tipo clock_t: un valor entero que indica una cantidad de "tics" de reloj.

La precisión que tenemos con dicha rutina es de CLOCKS_PER_SEC (tics de reloj por segundo), lo que significa que por cada segundo que pasa, la función clock() nos devolverá CLOCKS_PER_SEC unidades más que el valor anterior. En MinGW, CLOCKS_PER_SEC es igual a 1000, pero es mejor no fiarse de esto, ya que en otras plataformas dicho valor varía. Inclusive, según POSIX, la constante CLOCKS_PER_SEC debería ser 1000000.

Veamos algo de código:
#include <stdio.h>
#include <time.h>

int main(int argc, char *argv[])
{
clock_t t_ini, t_fin;
double secs;

t_ini = clock();
/* ...hacer algo... */
t_fin = clock();

secs = (double)(t_fin - t_ini) / CLOCKS_PER_SEC;
printf("%.16g milisegundos\n", secs * 1000.0);
return 0;
}
Con esto podemos medir cuántos milisegundos demoró "hacer algo". Todo parece muy bonito hasta que nos damos cuenta de dos grandes problemas:
  1. Tomar una medida única y aislada es igual que tomar un número completamente aleatorio y mostrarlo (no es una muestra representativa). Es mejor repetir las mediciones unas cuantas veces (y hablo del orden de las 100, o 100000, o 1e32 veces), y luego sacar un promedio de todo.
  2. La función clock() no llega a tener una precisión ni de 10 milisegundos (aunque CLOCS_PER_SEC sea 1000 o más).
Una vez dicho esto, el código de arriba no sirve ni para limpiarse los trastes... Así que tenemos que buscar una función con mayor precisión, y además, promediar varias muestras.

Existen otras alternativas como la función gettimeofday, pero bajo Windows sufre del mismo problema de precisión que clock(). Igualmente en Linux funciona perfectamente, así que vale la pena tener en cuenta este código:
#include <stdio.h>
#include <time.h>
#include <sys/time.h>

/* retorna "a - b" en segundos */
double timeval_diff(struct timeval *a, struct timeval *b)
{
return
(double)(a->tv_sec + (double)a->tv_usec/1000000) -
(double)(b->tv_sec + (double)b->tv_usec/1000000);
}

int main(int argc, char *argv[])
{
struct timeval t_ini, t_fin;
double secs;

gettimeofday(&t_ini, NULL);
/* ...hacer algo... */
gettimeofday(&t_fin, NULL);

secs = timeval_diff(&t_fin, &t_ini);
printf("%.16g milliseconds\n", secs * 1000.0);
return 0;
}
Como puede ver la estructura timeval contiene dos campos, segundos y microsegundos transcurridos (tv_sec y tv_usec respectivamente), por lo tanto ofrece una precisión de microsegundos. De todas formas, como decía esto en Windows no sirve y la razón es sencilla, en la misma MSDN explican que el temporizador del sistema corre aproximadamente a unos 10 milisegundos, por lo tanto, cualquier función que lo utilice nos estará dando la misma asquerosa precisión (inclusive al utilizar GetSystemTimeAsFileTime y FILETIME). Por lo tanto la solución es utilizar lo que se conoce en el mundo de Windows como el "contador de rendimiento de alta resolución" (high-resolution performance counter):
#include <stdio.h>
#include <windows.h>

/* retorna "a - b" en segundos */
double performancecounter_diff(LARGE_INTEGER *a, LARGE_INTEGER *b)
{
LARGE_INTEGER freq;
QueryPerformanceFrequency(&freq);
return (double)(a->QuadPart - b->QuadPart) / (double)freq.QuadPart;
}

int main(int argc, char *argv[])
{
LARGE_INTEGER t_ini, t_fin;
double secs;

QueryPerformanceCounter(&t_ini);
/* ...hacer algo... */
QueryPerformanceCounter(&t_fin);

secs = performancecounter_diff(&t_fin, &t_ini);
printf("%.16g milliseconds\n", secs * 1000.0);
return 0;
}
En este caso, imagine que QueryPerformanceCounter es como clock() y QueryPerformanceFrequency es como CLOCKS_PER_SEC. Es decir, la primera función nos da el valor del contador, y la segunda su frecuencia (en ciclos por segundo, hertz). Cabe aclarar que un LARGE_INTEGER es una forma de representar un entero de 64 bits por medio de una unión (union).

Como tarea al lector, si es que existe alguno, le queda hacer una versión "portable" (entre Windows y Linux) para medir el rendimiento (con unos cuantos #ifdef WIN32 y #endif sería suficiente).

18 de Marzo del 2008: acá transcribo una macro que me pasó el amigo Carlos Becker para medir el tiempo de una rutina en Linux mediante clock_gettime:
#define TIME_THIS(X)                                         \
  {                                                          \
    struct timespec ts1, ts2;                                \
    clock_gettime( CLOCK_REALTIME, &ts1 );                   \
    X;                                                       \
    clock_gettime( CLOCK_REALTIME, &ts2 );                   \
    printf( #X " demora: %f\n",                              \
      (float) ( 1.0*(1.0*ts2.tv_nsec - ts1.tv_nsec*1.0)*1e-9 \
      + 1.0*ts2.tv_sec - 1.0*ts1.tv_sec ) );                 \
  }

/* podemos usarla así */
{
  double x, y, z;
  x = 2.0;
  y = 4.0;
  TIME_THIS(z = sqrt(x*x + y*y));
}
Lo que da como resultado:
z = sqrt(x*x + y*y) demora: 0.015164

 01 March 2008 | cpp programacion optimizacion tiempo