Medición del rendimiento del código en python

A la hora de programar siempre hay diferentes formas de hacer la misma cosa. En ocasiones nos interesará saber cual es el código más rápido para hacer una tarea, es decir cual nos da un mejor rendimiento.

Veámoslo con un ejemplo sencillo. Imaginemos que tenemos una lista en python y queremos saber el valor de la suma de todos sus elementos:

lista=[10,15,67,45,23,423,12,22,4,56,13,22,78,98,1,43,56,22,31,11,23,56,78,22]

Podemos utilizar el comando sum, para sumar los elementos de la lista, o bien utilizar un bucle for para ir sumando los elementos uno a uno. Para saber cual es más eficiente una de las múltiples formas es usando el comando default_timer de la librería timeit.

El asunto funciona de la siguiente forma. Creamos una variable donde al comienzo del código que queremos medir establecemos el tiempo actual. Una vez ejecutado el código a medir, volvemos a estampar en la misma variable el tiempo actual. Por diferencia entre esta última y la primera vemos lo que ha tardado el código en ejecutarse. Vamos a verlo. Creamos un archivo nuevo de python y lo llamamos rendimiento.py

rendimiento.py

from timeit import default_timer
# Importamos la libreria que necesitamos para medir el tiempo

lista = [10, 15, 67, 45, 23, 423, 12, 22, 4, 56, 13,
         22, 78, 98, 1, 43, 56, 22, 31, 11, 23, 56, 78, 22]

# Suma de la lista utilizando SUM
contador = default_timer()
print(sum(lista))
t1 = default_timer()-contador
print(format(t1, 'f'))

# Suma de la lista con un bucle for
contador = default_timer()
resultado2 = 0
for i in lista:
    resultado2 = resultado2 + i
print(resultado2)
t2 = default_timer()-contador
print(format(t2, 'f'))

print(t1>t2)

Si lo ejecutamos veremos el siguiente resultado:

1231
0.000096
1231
0.000009
True

Como vemos por el resultado la función sum es menos eficiente que utilizar un bucle for ya que su tiempo de ejecución es mayor.

Nota: Como el resultado es un número muy pequeño de tiempo, la variable t sale en formato científico. Para poder ver el número más claro a simple vista voy a formatear la salida con la función format aplicada a la variable t aplicando el parametro 'f'.

Otra forma de hacer lo mismo es importando el método process_time() de la librería time.

rendimiento.py

from time import process_time
# Importamos la libreria que necesitamos para medir el tiempo

lista = [10, 15, 67, 45, 23, 423, 12, 22, 4, 56, 13,
         22, 78, 98, 1, 43, 56, 22, 31, 11, 23, 56, 78, 22]

# Suma de la lista utilizando SUM
t0 = process_time()
print(sum(lista))
t1 = process_time()
print("Tiempo transcurrido con SUM", format((t1-t0), "f"))

# Suma de la lista con un bucle for
t2=process_time()
resultado2=0
for i in lista:
    resultado2=resultado2 + i
print(resultado2)
t3=process_time()
print("Tiempo Transcurrido con bucle FOR ", format((t3-t2),"f"))
print((t1-t0)>(t3-t2))

Cuya salida es:

1231
Tiempo transcurrido con SUM 0.000045
1231
Tiempo Transcurrido con bucle FOR  0.000023
True

Lo que nos sigue confirmando que usar SUM es menos eficiente que usar un bucle For para sumar los elementos de la lista.

Una tercera forma, si estás en Linux, es usar la instrucción 'time'. Al ejecutarlo obtendremos tres comandos:

• Real: hace referencia al tiempo transcurrido entre la ejecución y la finalización del proceso.
• User: es la cantidad de tiempo de CPU gastado en modo usuario (fuera del núcleo) durante la ejecución del proceso.
•  Sys: es la cantidad de tiempo de CPU que transcurre en el núcleo al ejecutar el proceso.

Vamos a ver un ejemplo. Creamos un primer archivo para ver cuando tarda en ejecutarse la suma de nuestra lista.

uno.py

lista = [10, 15, 67, 45, 23, 423, 12, 22, 4, 56, 13,
         22, 78, 98, 1, 43, 56, 22, 31, 11, 23, 56, 78, 22]

# Suma de la lista utilizando SUM
print(sum(lista))

y lo ejecutamos de esta forma para ver los resultados:

$ time python3 uno.py
1231

real	0m0,024s
user	0m0,012s
sys	0m0,008s

Y ahora creamos un segundo archivo 'dos.py' para hacer lo mismo pero a traves de un bucle for.

dos.py

lista = [10, 15, 67, 45, 23, 423, 12, 22, 4, 56, 13,
         22, 78, 98, 1, 43, 56, 22, 31, 11, 23, 56, 78, 22]

resultado2 = 0

# Suma de la lista utilizando FOR
for i in lista:
    resultado2=resultado2 + i
print(resultado2)

y ejecutamos de nuevo el comando 'time' para ver los resultados.

$ time python3 dos.py
1231

real	0m0,017s
user	0m0,010s
sys	0m0,007s

Lo que nos sigue confirmando el mismo resultado.

También nos puede ocurrir que tengamos un programa y para mejorar el rendimiento queramos saber que parte del mismo es el que esta gastando más recursos, el que esta utilizando más tiempo de computación, para intentar depurarlo y que se ejecute más rápido.

Para ver como las diferentes partes de un programa consumen los recursos, podemos utilizar el módulo cProfile.

Lo ejecutamos de la siguiente forma:

>>> python3 -m cProfile -o datos.dat rendimiento.py

Con esta instrucción le estamos diciendo a python3 que ejecute el modulo cProfile como un programa, con -o le decimos que guarde los resultados en el archivo datos.dat (puede tener el nombre que quieras) y para finalizar ponemos el nombre del programa a testear, en mi caso rendimiento.py

>>> python3 -m cProfile -o datos.dat rendimiento.py
1231
Tiempo transcurrido con SUM 0.000072
1231
Tiempo Transcurrido con bucle FOR  0.000011
True

Luego para ver las estadísticas que se han generado utilizamos un módulo que también viene dentro de python que es pstats

>>>pyhton -m pstats datos.dat

donde datos.dat es el nombre del archivo que generamos en el punto anterior.

Comandos de pstats:

help – para obtener información

Tecleamos:

1.) strip

Para acortar las rutas de los nombre de los módulos y que se vea mejor.

2.) sort time 

Para que nos ordene los datos por tiempo de ejecución. Se puede ordenar por otros campos.

3.) stats 10 

Para que nos muestre por pantalla las estadísticas, en este caso limitado a 10

resultados para que no nos sature la pantalla.

>>>python3 -m pstats datos.dat
Welcome to the profile statistics browser.
datos.dat% strip
datos.dat% sort time
datos.dat% stats 10
Tue Dec 15 19:53:12 2020    datos.dat

         15 function calls in 0.000 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        5    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        1    0.000    0.000    0.000    0.000 rendimiento.py:1(<module>)
        4    0.000    0.000    0.000    0.000 {built-in method time.process_time}
        2    0.000    0.000    0.000    0.000 {built-in method builtins.format}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {built-in method builtins.sum}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}


datos.dat% 

En este caso al ser un programa tan sencillo no nos aporta mucha información sobre los cuellos de botella del programa. Sin embargo si utilizamos por ejemplo este otro programa (paciencia que hace 16.000.000 de cálculos y tarda un poco), lo llamamos prueba.py  y aplicamos lo visto:

$ python3 -m cProfile -o data.dat prueba.py
Probabilidad= 0.7854415625
El numero estimado de pi= 3.14176625
El error para 16000000 REPETICIONES es de -0.00017

$ python3 -m pstats data.dat
Welcome to the profile statistics browser.
data.dat% strip
data.dat% sort time
data.dat% stats 10
Wed Dec 16 11:03:25 2020    data.dat

         32000717 function calls (32000690 primitive calls) in 15.398 seconds

   Ordered by: internal time
   List reduced from 101 to 10 due to restriction <10>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   13.086   13.086   15.398   15.398 prueba.py:4(<module>)
 32000000    2.310    0.000    2.310    0.000 {method 'random' of '_random.Random' objects}
        2    0.000    0.000    0.000    0.000 {built-in method marshal.loads}
        3    0.000    0.000    0.000    0.000 {built-in method builtins.print}
        2    0.000    0.000    0.000    0.000 {built-in method io.open_code}
        4    0.000    0.000    0.000    0.000 {built-in method _imp.create_builtin}
       10    0.000    0.000    0.000    0.000 {built-in method posix.stat}
        1    0.000    0.000    0.001    0.001 random.py:1(<module>)
        6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external>:1431(find_spec)
      6/1    0.000    0.000    0.002    0.002 <frozen importlib._bootstrap>:986(_find_and_load)


data.dat% 

Observamos como el modulo en su conjunto tarda 15.398 segundos en ejecutarse y que la principal carga de trabajo esta en el método random al que se hacen 32.000.000 millones de llamadas y es lo que mas procesamiento ocupa de cálculo de todo el programa.

En una próxima entrada veremos como se acelera enormemente la velocidad de cálculo si usamos la librería numpy con este mismo programa, de 15 segundos a prácticamente 1 segundo.