Ejemplos java y C/linux

Tutoriales

Enlaces

Licencia

Creative Commons License
Esta obra está bajo una licencia de Creative Commons.
Para reconocer la autoría debes poner el enlace http://www.chuidiang.com

El profiler de C en Linux

A veces usamos algoritmos más o menos complejos y nuestro programa va demasiado lento, tenemos que depurarlo y acelerarlo como sea.

No es una buena técnica ir a lo loco a mejorar el código. Podemos pasarnos dos días intentando mejorar el código de la función que creemos que pierde el tiempo, probar, y ver que todo sigue igual de lento. El tiempo a lo mejor se está perdiendo en otra función que ni siquiera se nos pasa por la cabeza, quizás sea una función muy simple, pero se la llama muchísimas veces (para un ejemplo real, mira al final)

Linux proporciona varias herramientas que nos permiten analizar nuestro programa en ejecución y ver en qué gasta el tiempo( prof, gprof, monitor, etc). Aquí vamos a echarle un ojo a gprof.

En primer lugar, vamos a hacer un programita que llamaremos pprofiler.c y que únicamente se dedique a perder tiempo. Puede ser algo así como:

void funcion1();     /* prototipo de una de las funciones */
void funcion2();        /* protoripo de la otra función */

/* Programa principal.
 * Llama 1000 veces a cada una de las funciones funcion1() y funcion2() */
main()
{
    int i;
    for (i=0; i<1000; i++)
   {
        funcion1();
        funcion2();
     }
}

/* funcion1(). Pierde el tiempo */
void funcion1()
{
    int i,j;
    for (i=0;i<10;i++)
        for(j=0;j<1000;j++);
}

/* funcion2(). Pierde más tiempo */
void funcion2()
{
    int i,j;
    for (i=0;i<1000;i++)
        for (j=0;j<1000;j++);
}

Como puedes ver, simplemente hay dos funciones con unos bucles para perder el tiempo. En la realidad, estas y otras como estas serían tus funciones con tu código y tus algoritmos.

Para usar gprof,  lo única que hay que hacer es compilar con la opción -pg y ejecutar el programa

$ cc -pg pprofiler.c -o pprofiler
$ ./pprofiler

Cuando termine de ejecutarse el programa, se generará automáticamente un fichero gmon.out, que es el fichero en el que se guardan las estadísticas de tiempo de nuestro programa y de nuestras funciones. Es importante dejar que el programa termine de forma natural (sin abortarlo), ya que si no este fichero gmon.out puede quedar incompleto y no ser de utilidad. Si nuestro programa es de los que debe estar permanentemente arrancado y no salir nunca, debemos ponerle una opción para salir. Podemos, por ejemplo, capturar la señal de ctrl-c para hacer un exit() en condiciones.

Una vez que tenemos el fichero, con el comando gprof miprograma, obtendremos en pantalla las estadísticas de tiempo. Para el ejemplo concreto, yo he obtenido lo siguiente:

$ gprof pprofiler
Flat profile:
Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total 
 time   seconds   seconds    calls  us/call  us/call  name 
 99.41     10.09    10.09     1000 10090.00 10090.00  funcion2
  0.59     10.15     0.06     1000    60.00    60.00  funcion1
....  aqui va una explicación de lo que es cada columna ... br/> granularity: each sample hit covers 4 byte(s) for 0.10% of 10.15 seconds
index % time    self  children    called     name
                                                 <spontaneous>
[1]    100.0    0.00   10.15                 main [1]
               10.09    0.00    1000/1000        funcion2 [2]
                0.06    0.00    1000/1000        funcion1 [3]
-----------------------------------------------
               10.09    0.00    1000/1000        main [1]
[2]     99.4   10.09    0.00    1000         funcion2 [2]
-----------------------------------------------
                0.06    0.00    1000/1000        main [1]
[3]      0.6    0.06    0.00    1000         funcion1 [3]
-----------------------------------------------
... otra explicación de lo que es cada campo ...

Si tienes un ordenador más moderno que el mio (cosa bastante probable) y te salen todos los tiempos de 0.0, quizás debas hacer los bucles más largos.

En primer lugar nos aparece una tabla con las funciones de nuestro programa ordenadas de más consumidora de tiempo a menos. Las funciones que gastan tiempo 0.0 (o despreciable, como el main() en nuestro caso), no aparecen por defecto.  Vemos que la funcion2() ha gastado el 99.41% del tiempo de ejecución de nuestro programa, funcion1() el 0.59% y main(), que ni siguiera aparece, un 0% (por eso no aparece).

Ha habido 1000 llamadas a cada función y mientras que funcion2() tarda 10090 microsegundos por llamada, funcion1() sólo tarda 60 microsegundos.

En la segunda tabla que sale, tenemos además una especie de árbol de llamadas. Indica que el 100% del tiempo (10.15 segundos) se ha estado ejecutando la funcion main(). Esta función ha llamado 1000 veces a funcion1() y otras 1000 veces a funcion2(). También están los tiempos empleados en estas llamadas.

Luego aparece funcion2(), en la que se ha estado el 99.4% del tiempo y que ha sido llamada por main() 1000 veces.

etc, etc.

Todo esto nos facilita el saber exactamente que función debemos depurar. Debemos ir en primer lugar a la primer función que aparece en la primera tabla. Ver si se la ha llamado muchas veces o si gasta mucho tiempo en cada llamada. En función de eso, debemos tratar de llamarla menos veces o bien hacer que tarde menos.

Una experiencia personal

En cierta ocasión estaba haciendo un programa que debía pintar una imagen en blanco y negro en pantalla. La imágen me la daba codificada un equipo hardware, cuyos datos debía leer en tiempo real, decodificar a unos y ceros (uno era un pixel negro y cero un pixel blanco) y luego pintar. La codificación era un código Huffman (para el que le suene), cuyo algoritmo de decodificación es bastante complejo.

Una vez hecho el programa, el equipo daba los datos más deprisa de lo que yo era capaz de pintarlos. Puesto que el pintado era relativamente fácil (un uno, se pinta un pixel negro, un cero se pinta un pixel blanco), pensé inmediatamente que era culpa del algoritmo de decodificación, así que lancé el profiler para ver qué parte del algoritmo era más lenta.

¡ Sorpresa !, la mayor parte del tiempo, y con mucha diferencia, se iba en la función a la que se le pasaba un array de unos y ceros y devolvía un array con los índices de color blanco y negro para pintar. Ni se perdía el tiempo en el algoritmo ni en el pintado, sino en una función tan tonta como

void damePixels (char *bit, int *pixel, int nPuntos)
{
    int i;
    for (i=0; i<nPuntos; i++)
    {
        if (bit[i] == 1)
            pixel[i] = negro;
        else
           pixel[i] = blanco;
    }
}

La solución fue hacer que el algorimo de decodificación admitiera los índices de color correspondientes a blanco y negro y decodificara dando directamente los colores, en vez de 1 y 0, evitando así la llamada a esta función. El programa se aceleró muchísimo y fue capaz de pintar el gráfico en tiempo real.

Estadísticas y comentarios

Numero de visitas desde el 4 Feb 2007: