Profiling de código Python

Medir primeiro, otimizar depois

Um backtest de quatro horas ou uma função de precificação chamada um milhão de vezes por segundo fazem todos quererem acelerar, e quase todos erram sobre para onde vai o tempo. O laço que parece pesado pode não custar nada; uma linha de aparência inocente pode ser a execução inteira. Profiling é medir onde um programa gasta o tempo antes de mudar qualquer coisa. A regra é simples: não otimize uma linha que você não mediu e, depois de uma mudança, meça de novo para ver se ajudou.

# 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

Ruído, repetições e o mínimo

Uma única medição não é confiável: o sistema operacional, outros programas, o cache da CPU e a inicialização do Python acrescentam ruído, e só acrescentam tempo. Por isso cronometre a função várias vezes e pegue o mínimo, a execução menos perturbada; o timeit faz exatamente isso. Use time.perf_counter() (um relógio monotônico de alta resolução), não time.time(). Meça com tamanhos de entrada realistas, pois uma função rápida com dez linhas pode ser lenta com dez milhões, e aqueça antes para que custos únicos (imports, caches) não sejam cobrados do 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

Para onde vai o tempo: profilers e a lei de Amdahl

Um cronômetro diz quanto, um profiler diz onde. O cProfile da biblioteca padrão registra cada chamada de função e informa, para cada uma, quantas chamadas recebeu, o tempo gasto na própria função e o tempo acumulado incluindo o que ela chamou; python -m cProfile -s cumtime script.py mostra os piores primeiro. A participação de cada função é então simplesmente seu tempo sobre o total. O ganho de consertar uma é limitado pela lei de Amdahl: acelerar uma fração f da execução por um fator s dá, no total, 1 / ((1 - f) + f / s). Tornar 60 % de uma execução dez vezes mais rápido dá só 2,2 vezes no total, e mesmo uma metade infinitamente rápida limita o ganho a 2. Ataque primeiro o maior ponto quente.

# 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

• Meça antes de mudar qualquer coisa; cronometre com perf_counter, repita e fique com o mínimo, com tamanhos de entrada realistas.
• Um profiler (cProfile) mostra para onde vai o tempo: chamadas, tempo próprio e acumulado por função; cada participação é seu tempo sobre o total.
• Lei de Amdahl: acelerar uma fração f por um fator s dá 1 / ((1 - f) + f / s); conserte primeiro o maior ponto quente e meça de novo após cada mudança.

A seguir: otimização de laços críticos, as mudanças que aceleram o código apontado pelo profiler.

Lab: o que é avaliado

• Cronometrar uma chamada com time_call25 pts
• Pegar o melhor de várias execuções com best_of25 pts
• Achar para onde vai o tempo com hotspots25 pts
• Prever o ganho com amdahl_gain25 pts