Ojo con las trazas en python

En el proyecto que estoy actualmente hemos llegado a un punto en que lo que tenemos montado puede ser ya usado, funcionalmente. Pero nos quedaba una incógnita por resolver. ¿Es lo suficientemente rápido?

El sistema tiene que procesar documentos html, para lo cual en primer lugar usamos Tidy, luego se parsean, y los transformamos a nuestro formato interno.

El uso de Tidy es necesario ya que el parser de python (HTMLParser) no se traga cualquier cosa.

En un futuro seguramente usemos algún otro parser implementado en un lenguaje de mas bajo nivel y que valide, pero de momento el sistema actual nos ha servido para avanzar en el desarrollo.

Para la primera toma de tiempos usé simplemente la función time.time. Tomando tiempos con las trazas activadas y desactivadas. Mi sorpresa es que tidy no era lo que se llevaba mas tiempo (escribe el documento totalmente), sino que nuestra parte se llevaba mas.

Para seguir analizando, decidí usar el profiler de python, ya que nunca lo había usado.
La forma mas sencilla de uso es:



python profile.py <script> <args>



Su salida de texto, ya me sirvió para ver alguna cosilla sospechosa dentro del código (que no del parser).
De todas formas es mas potente usándolo dentro del código, ya que el fichero generado es binario:




import profile
profile.run(<funcion>,<fichero>)



Posteriormente a través del módulo pstats, se puede postprocesar:



import pstats
import sys

file = sys.argv[1]
p = pstats.Stats(file)
p.sort_stats('cumulative')
p.print_stats()



El profiler me orientó, sobre la zona del código con los problemas.
A partir de ahí usé una librería hecha a medida para la toma de tiempos. La ventaja de la librería sobre el profiler, es que el profiler te da el tiempo por llamada, y la librería de toma de tiempos te da mas libertad, ya que tu defines la porción de código que entra en la toma de tiempo.

Una vez tengamos este tipo de librería lo suyo es que dejemos el código instrumentado con ellas en sitios clave, y que mediante configuración podamos activar o desactivar la toma de tiempos.

Bueno que de desvío del tema... Con la librería vi que algo raro pasado. No era normal que una región de código que no hacía nada se llevase el tiempo que se estaba llevando. Hasta que me fijé en las dichosas trazas, que tenía desactivadas, y gualá. Di con el problema.

El problema de fondo es que vengo del desarrollo de C++ y allí normalmente cuando se desactivan las trazas, no se ejecuta ni la invocación.
Pero claro aquí estábamos con python, y con un recubrimiento del modulo de logging de python. La invocación ser realizaba, aunque la traza no se generase. Y lo que se estaba llevando el tiempo era la evaluación de los argumentos. Estaba pasando a string una estructura de datos bastante tocha.

Moraleja: ojito con la evaluación de los argumentos en las trazas.

De todas formas a posteriormente me he dado cuenta de que fui un gañán y que a veces no vemos lo que no queremos ver. Ya que en la salida del profiler salía que el logging era lo que se estaba llevando el tiempo. Pero claro como estaba desactivado el nivel DEBUG...

Diseño de librería de toma de tiempos

Continuando con este tema...

Como he indicado anteriormente la toma de tiempos se debe de poder activar y desactivar por configuración y a los tiempos se les asigna una marca o tag.

En el diseño original, la librería tenia dos métodos para una determinada marca; uno para el comienzo de toma de tiempo y otro para el final de toma de tiempo.
Esto tiene como problema el que se te puedan quedar marcas desbalanceadas.

Un diseño mejor, es que en lugar de definir un comienzo y fin de marca y se vayan acumulando los tiempos, lo que hagamos es para cada marca registrar el tiempo.
Una vez terminada la ejecución se pedirán los tiempos. Cuando se pidan los tiempos es cuando se calculan los acumulados. Para calcular los acumulados, será necesario indicar entre que marcas se van a hacer los cálculos.