Profiling de código Python

Medir primero, optimizar después

Un backtest de cuatro horas o una función de valoración llamada un millón de veces por segundo hacen que todos quieran acelerar, y casi todos se equivocan sobre adónde va el tiempo. El bucle que parece pesado puede no costar nada; una línea de aspecto inocente puede ser toda la ejecución. El perfilado consiste en medir dónde gasta su tiempo un programa antes de cambiar nada. La regla es simple: no optimices una línea que no hayas medido y, tras un cambio, mide de nuevo para ver si ayudó.

# The simplest measurement: read a clock before and after
import time

def slow_sum(n):
    total = 0
    for i in range(n):
        total += i * i
    return total

start = time.perf_counter()
result = slow_sum(200_000)
elapsed = time.perf_counter() - start
print(result)                                        # 2666646666700000
print(elapsed > 0)                                   # True  a real duration; the exact value changes every run

Ruido, repeticiones y mínimo

Una sola medición no es fiable: el sistema operativo, otros programas, la caché de la CPU y el arranque de Python añaden ruido, y solo añaden tiempo. Por eso se cronometra una función varias veces y se toma el mínimo, la ejecución menos perturbada; timeit hace justo eso. Usa time.perf_counter() (un reloj monótono de alta resolución), no time.time(). Mide con tamaños de entrada realistas, porque una función rápida con diez filas puede ser lenta con diez millones, y calienta antes para que los costes únicos (imports, cachés) no se carguen al código medido.

# Repeat and take the minimum: the least disturbed run
import time

def work():
    return sum(i * i for i in range(50_000))

def best_of(func, repeats):
    best = None
    for _ in range(repeats):
        start = time.perf_counter()
        func()
        elapsed = time.perf_counter() - start
        if best is None or elapsed < best:
            best = elapsed
    return best

runs = [best_of(work, 1) for _ in range(5)]
print(best_of(work, 5) <= max(runs))                 # True  the minimum is never above the worst single run
print(min(runs) > 0)                                 # True

Adónde va el tiempo: perfiladores y la ley de Amdahl

Un cronómetro dice cuánto, un perfilador dice dónde. cProfile, de la biblioteca estándar, registra cada llamada a función e informa, para cada una, cuántas llamadas recibió, el tiempo gastado en la propia función y el tiempo acumulado incluyendo lo que llamó; python -m cProfile -s cumtime script.py muestra primero lo peor. La parte de cada función es entonces su tiempo sobre el total. La ganancia de arreglar una está limitada por la ley de Amdahl: acelerar una fracción f de la ejecución en un factor s da en total 1 / ((1 - f) + f / s). Hacer 60 % de una ejecución diez veces más rápido da solo 2,2 veces en total, e incluso una mitad infinitamente rápida limita la ganancia a 2. Ataca primero el mayor punto caliente.

# Shares of the total and the payoff of fixing the biggest one (the timings are made-up numbers)
timings = {"load_prices": 6.0, "price_options": 3.0, "write_report": 1.0}
total = sum(timings.values())
for name, seconds in sorted(timings.items(), key=lambda item: -item[1]):
    print(f"{name:14s} {seconds / total:5.1%}")      # load_prices 60.0%, price_options 30.0%, write_report 10.0%

def amdahl_gain(fraction, speedup):
    return 1 / ((1 - fraction) + fraction / speedup)

print(round(amdahl_gain(0.6, 10), 2))                # 2.17  ten times faster on 60% of the run
print(round(amdahl_gain(0.1, 1000), 2))              # 1.11  a huge win on the smallest part barely helps

# cProfile records every call; the function that sleeps shows up as the hotspot
import cProfile
import time

def slow_part():
    time.sleep(0.02)

def fast_part():
    return sum(range(10))

def run_all():
    slow_part()
    for _ in range(100):
        fast_part()

profiler = cProfile.Profile()
profiler.runcall(run_all)
entries = {str(entry.code): entry for entry in profiler.getstats()}
slow = next(entry for name, entry in entries.items() if "slow_part" in name)
fast = next(entry for name, entry in entries.items() if "fast_part" in name)
print(fast.callcount, slow.callcount)                # 100 1   calls are counted exactly
print(slow.totaltime > fast.totaltime)               # True    one slow call outweighs 100 fast ones

• Mide antes de cambiar nada; cronometra con perf_counter, repite y quédate con el mínimo, con tamaños de entrada realistas.
• Un perfilador (cProfile) muestra adónde va el tiempo: llamadas, tiempo propio y acumulado por función; cada parte es su tiempo sobre el total.
• Ley de Amdahl: acelerar una fracción f en un factor s da 1 / ((1 - f) + f / s); arregla primero el mayor punto caliente y vuelve a medir tras cada cambio.

A continuación: optimizar bucles críticos, los cambios que aceleran el código señalado por el perfilador.

Lab: qué se califica

• Cronometrar una llamada con time_call25 pts
• Tomar lo mejor de varias ejecuciones con best_of25 pts
• Hallar adónde va el tiempo con hotspots25 pts
• Predecir la ganancia con amdahl_gain25 pts