Optimizar nuestros programas, ¿dónde?

Seguro que alguna vez nos hemos preguntado, una vez finalizado un programa, cómo podríamos mejorarlo para que fuera más eficiente.

En proyectos muy pequeños, casi triviales, puede ser muy sencillo averiguar qué partes del programa podríamos cambiar para mejorar el rendimiento total de la aplicación, pero cuando los fuentes son muy grandes o la aplicación tiene cierta complejidad, resulta muy difícil acertar incluso para programadores experimentados.

Así que para facilitarnos las cosas existen los profilers (perfiladores, porque realizan perfiles... traducción libre mía :D), que son herramientas que nos permiten monitorizar un programa para poder analizar su rendimiento, mediante el análisis de información recogida en tiempo de ejecución.

El uso de estos programas permite, por una parte, averiguar qué piezas de código se ejecutan con más frecuencia (candidaturas para la optimización), y además descubrir errores (código que se ejecuta con más o menos frecuencia de lo esperado).

Como pasa habitualmente cuando hablamos de herramientas de desarrollo, en el mundo del Software Libre tenemos varias alternativas ;). Al trabajar con OpenBSD voy a utilizar gprof(1) (soporta C, Pascal y Fortran77), que está disponible en la base de esta espléndida plataforma de desarrollo (ojo que no es el GNU Profiler que viene en las GNU Binutils, pero sí compatible).

Como no tengo experiencia con este tipo de herramientas, he probado con bogom (concretamente la última versión estable: 1.7.1) a ver si podemos sacar alguna conclusión.

La compilación de bogom es sencilla, y para activar el profiler solo hay que emplear la opción del compilador -pg e indicar que se deben usar las librerías para profiling (tienen el sufijo _p):

$ make CFLAGS+=-pg LDFLAGS+=-pg LIBS="-lmilter_p -lpthread_p"
cc  -pg -pg -Wall -g -c milter.c -o bogom.o
cc  -pg -pg -Wall -g -c conf.c -o conf.o
cc -pg -o bogom bogom.o conf.o -lmilter_p -lpthread_p

Para hacer la prueba no es necesario instalar el binario, solo detener la instancia que está corriendo en el sistema y lanzar este nuevo ejecutable.

Hay que tener en cuenta que cuando el programa finaliza normalmente se guardan en disco en el directorio de trabajo los datos obtenidos durante la ejecución (importante, no vale romper la aplicación), así que el milter debe poder escribir en su directorio de trabajo.

En mi instalación el programa se ejecuta como el usuario milter, así que cuando he arrancado bogom he llevado el cuidado de situarme en un directorio con permisos de escritura para ese usuario añadiendo una llamada a chdir(2) [1] después de ejecutar la función daemon(3) (porque daemon cambia el directorio de trabajo a /).

Por último comentar que he ejecutado el programa en modo verbose para tener información sobre los mensajes procesados.

# /home/reidrac/src/bogom/bogom -v
# ps U milter
  PID TT   STAT      TIME COMMAND
13714 ??  Is      0:00.00 /home/reidrac/src/bogom/bogom

Perfecto. Mediante ps verificamos que es el binario compilado especialmente.

Después de un tiempo razonable (unas 12 horas en mi caso, y así asegurarnos que hay suficiente tráfico de mensajes), para que se recoja información, terminamos el milter para recoger el fichero gmon.out donde se encuentra la información recogida.

Haciendo un análisis rápido de los logs vemos:

Recordemos que para que el profiling sea efectivo nuestra aplicación tiene que ser usada normalmente. En este caso el único elemento diferente ha sido la activación del modo verbose y, aunque no creo que eso afecte demasiado, habrá que tenerlo en cuenta al ver el informe.

Copiamos el fichero gmon.out en el directorio donde se encuentra el binario modificado de bogom, y el informe se obtiene mediante:

$ gprof bogom > gprof_bogom.txt

El informe comienza con una explicación de lo que vamos a leer, lo cual es muy útil ;).

Obtenemos dos sub-informes: call graph profile y flat profile. El primer caso tiene en cuenta las llamadas a función y las posteriores funciones que se llaman desde ahí, y el segundo solo cuenta las llamadas a función individuales [2].

Ahora voy a hacer algún comentario, aunque no tengo prácticamente ni idea de lo que hablo :P. El fichero completo se puede consultar: gprof_bogom.txt.

Empezando a ojear el primer informe me doy cuenta que tengo que ir a la entrada 9 para ver una función que haya programado yo :), las anteriores están todas relacionadas con las threads. Otra cosa que llama la atención es el tiempo: 0.50 segundos de consumo. Esto significa que las entradas anteriores han consumido más, aunque la que más tiempo ha ejecutado apenas ha estado 1 segundo.

Esto se explica porque en 12 horas el milter ha pasado la mayor parte del tiempo idle (solo 139 mensajes).

La información en el call graph profile está en forma de árbol: después de una función se analizan las llamadas a las funciones que parten de ella. Es complicado de analizar, y cuesta encontrar una función que llamemos nosotros y sea objetivo de estudio.

Por ejemplo, un punto candidato de estudio son las llamadas a regexec.

En el milter empleo expresiones regulares para identificar varias white list, o elementos que no deben ser filtrados. Por ejemplo, en la lista para comprobar la dirección IP de conexión tengo '192\.168\.0\.', lo cual evita que se filtre cualquier mensaje que venga de una conexión con dirección que contenga "192.168.0.".

Las expresiones regulares con complejas, y por lo tango (se supone) que su verificación es lenta. Se debe ejecutar un paso preliminar que convierte las expresiones a un formato compilado listo para comparar. Yo realizo la compilación al cargar la configuración buscando la máxima velocidad, y parece que surte efecto: tenemos que desplazarnos a la posición 149 para encontrar la llamada a regexec.

Por último voy a echarle un ojo al flat profile, aunque tampoco aquí veo funciones que claramente sean candidatas a optimizar.

Por poner un ejemplo, lo que primero me encuentro (siempre hablando de funciones que uso directamente en el milter) es una llamada fork con un 0.3% del tiempo consumido (vamos, nada :D). Ese es otro de los supuestos puntos débiles del milter, ya que tiene que crear un nuevo proceso para ejecutar bogofilter y que analice el mensaje. Si miramos el tiempo que hemos esperado al programa externo en el call graph profile (llamadas a waitpid), nos encontramos con un 0.4% en total en ese informe, lo que indica que en conjunto el tiempo dedicado a ejecutar bogofilter es despreciable.

Me ha sorprendido gratamente en comportamiento del milter porque, al menos, no he visto nada obvio en el informe, lo cual es bueno :D. Tampoco se ha sometido al programa a mucha carga, lo que podría cambiar las cosas y hacer que los puntos más débiles mostraran entonces más tiempo de ejecución (se me ocurre, por ejemplo, white lists muy largas).

Notas:
[1] se puede usar la variable de entorno PROFDIR para indicar en qué directorio se guardará la información, con lo que el hack del chdir no sería necesario.
[2] la función __mcount se emplea en el proceso de profiling y la podemos ignorar con -E __mcount al ejecutar gprof.