Análisis de rendimiento en Python

Análisis de rendimiento en Python

El análisis de rendimiento de código, comúnmente conocido como profiling, consiste en la caracterización del tiempo que un determinado programa emplea en cada una de sus funciones y métodos, y es una herramienta fundamental a la hora de estudiar y planificar la refactorización de código cuando es necesario mejorar el rendimiento de nuestras aplicaciones. Además, en el caso de Python, cuyo mayor (y probablemente único) punto débil es precisamente el rendimiento, cobra mayor importancia si cabe.

En este post explicaremos e ilustraremos algunas de las principales herramientas de profiling disponibles para Python, lo que nos servirá también para recordar ciertos aspectos teóricos y prácticos sobre complejidad computacional, lo que nunca viene mal ;). Todo el código está escrito para Python 2.7, pero su adaptación a Python 3 es trivial. Comencemos.

Tipos y estructuras de datos

En estos experimentos utilizaremos estructuras de datos lineales (listas y conjuntos, implementados por los tipos list y set), a los que añadiremos como tipo de dato tuplas de cadenas de caracteres (tipos tuple y str). Como dato básico utilizaremos tuplas de 100 cadenas de caracteres, cada una de las cuales estará formada por 10 letras minúsculas aleatorias. Estos datos se generarán a partir de la función random_tuple(), cuya definición mostramos a continuación:

from string import ascii_lowercase as low
from random import choice

def random_tuple():
    """
    Generates a random tuple of size 100 with strings of size 10 formed by
    only lowercase letters
    """
    return tuple(''.join(choice(low) for _ in xrange(10)) for _ in xrange(100))

Profiling básico: El módulo timeit

En ocasiones no resulta necesario disponer de complejas herramientas que analicen en detalle todo el flujo de control de la aplicación y midan el tiempo empleado en cada nivel de la jerarquía de llamadas a funciones y métodos. En estos casos, puede ser más que suficiente una simple comparativa o medición del tiempo que tarda en ejecutarse una determinada función. Para ello está especialmente diseñado el módulo timeit, que podemos emplear a través de su interfaz por línea de comandos, como una librería, o de la forma más cómoda y recomendable, como un magic de IPython.

It's Magic!

Para demostrar de forma simple el funcionamiento de timeit, comprobaremos experimentalmente la popular recomendación de que, si deseamos crear una lista en Python, siempre es preferible hacerlo a través de una list comprehension que mediante la adición de elementos de forma iterativa. Definimos por tanto dos funciones:

def slow_list_creation(n):
    lst = []
    for _ in xrange(n):
        lst.append(random_tuple())
    return lst

def fast_list_creation(n):
    return [random_tuple() for _ in xrange(n)]

Y obtenemos sus tiempos de ejecución para listas de tamaño 100. Para ello, en un terminal de IPython, es suficiente con ejecutar las siguientes sentencias:

In [1]: %timeit fast_list_creation(100)
10 loops, best of 3: 45.9 ms per loop

In [2]: %timeit slow_list_creation(100)
10 loops, best of 3: 45.2 ms per loop

Como vemos, %timeit se encarga automáticamente de seleccionar un número de veces adecuado para ejecutar la función y que la llamada no tarde demasiado, y a continuación imprime el mejor tiempo obtenido. En este caso, los resultados contradicen la hipótesis inicial, pues el tiempo empleado en la creación de la lista mediante adición es incluso inferior a la list comprehension, aunque la diferencia sea prácticamente inapreciable.

¿Qué ha pasado entonces? Pues una primera pista nos la puede dar la medición del tiempo empleado en generar los datos que introducimos en las listas:

In [3]: %timeit random_tuple()
1000 loops, best of 3: 449 µs per loop

¡Ya hemos identificado el problema! Si multiplicamos el tiempo de generación de cada tupla aleatoria por el número de elementos que generamos (100), prácticamente tenemos los 45ms que tarda la creación de cada una de las listas. Probamos entonces a redefinir las funciones de creación para evitar que la generación de los elementos nos introduzca tanto overhead.

def slow_list_creation(n):
    lst = []
    for _ in xrange(n):
        lst.append(tuple())
    return lst

def fast_list_creation(n):
    return [tuple() for _ in xrange(n)]

En este caso, simplemente añadimos tuplas vacías a nuestra lista. Repetimos el experimento:

In [5]: %timeit fast_list_creation(100)
100000 loops, best of 3: 7.9 µs per loop

In [4]: %timeit slow_list_creation(100)
100000 loops, best of 3: 11.7 µs per loop

Con estos nuevos resultados, vemos que efectivamente las list comprehension son aproximadamente un 35% más rápidas en la creación de listas que la clásica aproximación de añadir elementos iterativamente.

Ahora probamos a aumentar significativamente el tamaño de las listas creadas, introduciendo 10000 elementos:

In [5]: %timeit fast_list_creation(10000)
1000 loops, best of 3: 703 µs per loop

In [6]: %timeit slow_list_creation(10000)
1000 loops, best of 3: 1.09 ms per loop

Como vemos, en ambos casos el tiempo ha escalado linealmente, por lo que podemos concluir que, tal y como sería de esperar, la creación de listas en Python tiene un coste de orden O(n), y que las list comprehension tardan un 35% menos tiempo en generar una lista que el método iterativo clásico.

Profiling avanzado: El módulo cProfile

El módulo timeit sin duda es una herramienta muy útil a la hora de estudiar el comportamiento de nuestros programas, pero la información que puede proporcionarnos es en ocasiones muy limitada (como acabamos de ver, si el coste real se encuentra en una función de uso interno los resultados lo ocultarán, y no nos mostrarán lo que realmente pretendemos medir), y de hecho no puede considerarse una herramienta de profiling propiamente dicha. Para realizar un análisis detallado del rendimiento de una aplicación necesitamos algo más que una simple medida del tiempo de ejecución de funciones, y para ello disponemos del excelente módulo cProfile, incluido también en la librería estándar de Python.

Este módulo nos permite realizar un análisis pormenorizado del rendimiento dinámico de cualquier programa, analizando todo el grafo de llamadas a funciones y métodos, y mostrando el tiempo empleado en cada una de ellas, tanto en cada invocación individual como de forma acumulada a lo largo de toda la ejecución del programa.

La forma más cómoda de utilizar este módulo es a través de la línea de comandos, pasando como argumento el script que deseamos ejecutar. Como primer ejemplo, intentaremos repetir el primer experimento, comparando el rendimiento de crear una lista mediante list comprehension o añadiendo elementos de forma iterativa. El script a ejectuar es el siguiente, que nombraremos profiling_test.py:

from string import ascii_lowercase as low
from random import choice

def random_tuple():
    return tuple(''.join(choice(low) for _ in xrange(10)) for _ in xrange(100))

def slow_list_creation(n):
    lst = []
    for _ in xrange(n):
        lst.append(random_tuple())
    return lst

def fast_list_creation(n):
    return [random_tuple() for _ in xrange(n)]

for _ in xrange(100):
    slow_list_creation(100)
    fast_list_creation(100)

Algo importante a tener en cuenta es que, a diferencia de timeit, el módulo cProfile simplemente ejecuta una vez el script de entrada y mide el tiempo empleado en cada una de las funciones y métodos, sin intentar obtener de forma automática una medida estadística del tiempo empleado. Por lo tanto, hemos programado explícitamente en nuestro código la repetición de la tarea de creación de listas 100 veces. Ejecutamos el profiling con la siguiente orden:

:~$ python -m cProfile profiling_test.py 
         64050249 function calls in 14.232 seconds
   Ordered by: standard name
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    20000    0.204    0.000   18.747    0.001 profiling_test.py:12(random_tuple)
  2020000    0.906    0.000   18.543    0.000 profiling_test.py:17(<genexpr>)
      100    0.005    0.000    9.373    0.094 profiling_test.py:19(slow_list_creation)
      100    0.003    0.000    9.382    0.094 profiling_test.py:25(fast_list_creation)
        1    0.019    0.019   18.775   18.775 profiling_test.py:7(<module>)
        1    0.000    0.000    0.000    0.000 random.py:100(seed)
 20000000    8.434    0.000   10.395    0.000 random.py:271(choice)
        1    0.000    0.000    0.001    0.001 random.py:40(<module>)
        1    0.000    0.000    0.000    0.000 random.py:650(WichmannHill)
        1    0.000    0.000    0.000    0.000 random.py:72(Random)
        1    0.000    0.000    0.000    0.000 random.py:800(SystemRandom)
        1    0.000    0.000    0.000    0.000 random.py:91(__init__)
    10000    0.001    0.000    0.001    0.000 {method 'append' of 'list' objects}
  2000000    2.698    0.000   17.637    0.000 {method 'join' of 'str' objects}
 20000000    0.992    0.000    0.992    0.000 {method 'random' of '_random.Random' objects}

Ante estos resultados, podemos ver inmediatamente que prácticamente todo el tiempo de ejecución se concentra en la función random_tuple(), mientras que la diferencia entre las funciones slow_list_creation() y fast_list_creation() es casi indistinguible.

Estos resultados nos muestran un nivel de detalle muy superior al de la simple medición de tiempos de ejecución, pero su análisis todavía resulta tedioso, y es extremadamente complicado analizar el flujo de llamadas que se lleva a cabo en el programa. Para ayudarnos en esta tarea, utilizaremos una excelente herramienta compatible con cProfile, denominada RunSnakeRun. Se trata de un visualizador gráfico de resultados de cProfile, que hace infinitamente más sencillo el análisis de rendimiento de una aplicación.

Para demostrar el uso de RunSnakeRun, emplearemos un script ligeramente distinto, y que nos permitirá comprobar el rendimiento de distintos métodos de búsqueda en colecciones ordenadas, con diferentes órdenes de complejidad. El script utilizado a partir de ahora será el siguiente:

from string import ascii_lowercase as low
from random import choice
import bisect

def random_tuple():
    return tuple(''.join(choice(low) for _ in xrange(10)) for _ in xrange(100))

N = 5
STRL = sorted(random_tuple() for _ in xrange(N))
STRS = set(STRL)
istr = choice(STRL)

for _ in xrange(100000):
    STRL.index(istr)
    bisect.bisect_left(STRL, istr)
    STRS.__contains__(istr)

Este programa simplemente genera una lista de tuplas aleatorias de tamaño N (en este primer ejemplo N=5), crea un conjunto con los mismos elementos, y selecciona aleatoriamente una tupla de entre todas las generadas. A continuación, se realiza una búsqueda de la tupla seleccionada mediante tres métodos distintos:

  1. Búsqueda lineal en la lista, cuya complejidad es O(n). Esta búsqueda se realiza mediante el método index() del tipo list, que busca el índice de un determinado elemento recorriendo la lista por orden.
  2. Búsqueda binaria en la lista, con una complejidad O(log(n)). Para esta búsqueda utilizamos la función bisect_left() del módulo bisect.
  3. Búsqueda en el conjunto, con una complejidad O(1). Al tratarse de un tipo de dato no ordenado, simplemente comprobaremos si el elemento pertenece al conjunto, a través de la función __contains__().

Como todas son operaciones extremadamente rápidas, repetiremos las búsquedas 100000 veces para evitar que la generación del conjunto de datos eclipse el tiempo de cómputo que nos interesa medir.

Ejecutamos el script con cProfile almacenando la salida en un archivo de nombre prof_results, y a continuación abrimos este archivo con RunSnakeRun a través del comando runsnake.

:~$ python -m cProfile -o prof_results profiling_test.py
:~$ runsnake prof_results

Profiling con N=5

En la parte izquierda de la interfaz encontramos la misma información que se imprimía por consola al ejecutar directamente el script con cProfile, con la ventaja de que podemos reordenar la lista en función de distintos criterios como el número de llamadas, el tiempo de ejcución por cada llamada, el tiempo de ejecución acumulado, etc. En la parte derecha se muestra de forma muy intuitiva la jerarquía de llamadas de nuestro programa junto con la influencia de cada función en el tiempo total de ejecución. Si nos fijamos en este diagrama, vemos que sorprendentemente el método de búsqueda más lento es la búsqueda en un conjunto, cuya complejidad teórica es O(1), mientras que el método más rápido es la búsqueda lineal, que incluso funciona mejor que la búsqueda binaria.

Lo que intentamos ilustrar con este ejemplo es que a la hora de seleccionar estructuras de datos no debemos considerar solamente la complejidad teórica de cada una de las operaciones que vayamos a realizar, sino también el tamaño de la entrada que previsiblemente vamos a tener para cada una de ellas. El motivo de que la búsqueda en un conjunto sea tan lenta en este caso es que el tipo de dato que estamos utilizando (tuplas de 100 elementos) es relativamente complejo, y el cálculo de la función hash para determinar su presencia en el conjunto es costoso.

Repetimos el experimento, pero en este caso estableciendo la variable N=50.

Profiling con N=50

En este caso, vemos como el método más costoso ya es con diferencia la búsqueda lineal, mientras que también destaca el aumento proporcional del tiempo dedicado a la generación de la lista de datos. Sin embargo, en este ejemplo la búsqueda binaria sigue siendo más rápida que la búsqueda en el conjunto, que como era de esperar tarda exactamente lo mismo que en el caso anterior.

Por último, repetimos la prueba con N=1000.

Profiling con N=1000

Vemos que a partir de este tamaño de entrada el comportamiento ya es el teóricamente esperado. El método más rápido de búsqueda es la búsqueda en un conjunto, que sigue manteniendo su comportamiento constante, mientras que la práctica totalidad del tiempo de ejecución pasa a situarse en la búsqueda lineal y en la generación de los datos de entrada, que efectivamente escalan linealmente.

Y hasta aquí esta introducción sobre métodos y herramientas de profiling en Python. Cualquier duda o aportación que puedas hacernos en los comentarios por supuesto será más que bienvenida.

Deixa unha resposta

O teu enderezo electrónico non se publicará Os campos obrigatorios están marcados con *