Python-Code profilen

Erst messen, dann optimieren

Ein Backtest von vier Stunden oder eine Bewertungsfunktion, die eine Million Mal pro Sekunde aufgerufen wird, weckt bei allen den Wunsch nach Beschleunigung, und fast alle schätzen falsch, wohin die Zeit geht. Die Schleife, die schwer aussieht, kostet vielleicht nichts; eine harmlos wirkende Zeile kann der ganze Lauf sein. Profiling heißt messen, wo ein Programm seine Zeit verbringt, bevor man etwas ändert. Die Regel ist einfach: Optimieren Sie keine Zeile, die Sie nicht gemessen haben, und messen Sie nach einer Änderung erneut, ob sie geholfen hat.

# 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

Rauschen, Wiederholungen und das Minimum

Eine einzelne Messung ist unzuverlässig: Betriebssystem, andere Programme, CPU-Cache und Pythons Start fügen Rauschen hinzu, und sie fügen immer nur Zeit hinzu. Messen Sie eine Funktion daher mehrmals und nehmen Sie das Minimum, den am wenigsten gestörten Lauf; timeit tut genau das. Verwenden Sie time.perf_counter() (eine hochauflösende monotone Uhr), nicht time.time(). Messen Sie mit realistischen Eingabegrößen, denn eine Funktion, die bei zehn Zeilen schnell ist, kann bei zehn Millionen langsam sein, und wärmen Sie zuerst auf, damit einmalige Kosten (Importe, Caches) nicht dem gemessenen Code angerechnet werden.

# 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

Wohin die Zeit geht: Profiler und das Amdahlsche Gesetz

Eine Stoppuhr sagt, wie lange, ein Profiler sagt, wo. cProfile aus der Standardbibliothek zeichnet jeden Funktionsaufruf auf und berichtet je Funktion die Zahl der Aufrufe, die in der Funktion selbst verbrachte Zeit und die kumulative Zeit samt dem, was sie aufrief; python -m cProfile -s cumtime script.py zeigt die schlimmsten zuerst. Der Anteil jeder Funktion ist dann einfach ihre Zeit durch die Gesamtzeit. Der Gewinn einer Korrektur ist durch das Amdahlsche Gesetz begrenzt: Beschleunigt man einen Anteil f des Laufs um den Faktor s, ergibt sich insgesamt 1 / ((1 - f) + f / s). 60 % eines Laufs zehnmal schneller zu machen, bringt insgesamt nur das 2,2-Fache, und selbst eine unendlich schnelle Hälfte begrenzt den Gewinn auf 2. Gehen Sie zuerst den größten Hotspot an.

# 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

• Messen Sie vor jeder Änderung; mit perf_counter zeitnehmen, wiederholen und das Minimum behalten, bei realistischen Eingabegrößen.
• Ein Profiler (cProfile) zeigt, wohin die Zeit geht: Aufrufe, Eigen- und kumulative Zeit je Funktion; jeder Anteil ist seine Zeit durch die Gesamtzeit.
• Amdahlsches Gesetz: Beschleunigt man einen Anteil f um s, ergibt sich 1 / ((1 - f) + f / s); den größten Hotspot zuerst angehen und nach jeder Änderung neu messen.

Als Nächstes: Optimierung heißer Schleifen, die Änderungen, die den vom Profiler gezeigten Code beschleunigen.

Lab: Was bewertet wird

• Mit time_call einen Aufruf messen25 Pkt.
• Mit best_of den besten von mehreren Läufen nehmen25 Pkt.
• Mit hotspots herausfinden, wohin die Zeit geht25 Pkt.
• Mit amdahl_gain den Gewinn vorhersagen25 Pkt.