Zum Inhalt springen
aviral gupta

// A4.2 · ca. 30 Min. · Vertiefung

Profiling mit cProfile

Nach dieser Lektion profilieren Sie ein Programm mit cProfile, lesen ncalls, tottime und cumtime, sortieren und kürzen den Bericht mit pstats und finden die bremsende Funktion samt bestätigter Korrektur.

Lektion 2 von 5 in A4 Leistung und Zahlen

Danach können Sie

  • Code mit cProfile profilieren und ncalls, tottime und cumtime im Bericht lesen
  • Einen Bericht mit pstats sortieren und kürzen: sort_stats, print_stats und strip_dirs
  • Die heiße Funktion finden und eine Korrektur über ihre Aufrufzahl bestätigen, nicht per Vermutung
  1. Aufwärmen · Aufgabe 1 von 7

    Aufwärmen aus der timeit-Lektion: Ein ganzer Bericht braucht 3 Sekunden, und Sie wissen nicht, warum. Warum reicht timeit allein hier nicht?

  2. Vorhersagen · Aufgabe 2 von 7

    Sagen Sie es vorher, bevor Sie weiterlesen: fib ruft sich selbst auf. Was zeichnet das Profil als ncalls auf?

    import cProfile
    import pstats
    
    
    def fib(n):
        return n if n < 2 else fib(n - 1) + fib(n - 2)
    
    
    with cProfile.Profile() as profiler:
        fib(5)
    
    rows = pstats.Stats(profiler).get_stats_profile().func_profiles
    print(rows["fib"].ncalls)
  3. Üben · Aufgabe 3 von 7

    outer ruft light 50-mal und heavy einmal auf; heavy läuft eine lange Schleife. Setzen Sie den Schlüssel ein, damit die Funktion mit der meisten Zeit im eigenen Code vorn steht.

    stats.sort_stats(SortKey.____)
    stats.sort_stats(SortKey.)
  4. Üben · Aufgabe 4 von 7

    Hier ist ein echter Bericht. Welche Funktion verbringt die meiste Zeit im eigenen Code, ohne die Funktionen, die sie aufruft?

             9005 function calls in 0.257 seconds
    
       Ordered by: cumulative time
       List reduced from 7 to 5 due to restriction <5>
    
       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            1    0.000    0.000    0.257    0.257 main.py:20(report)
            1    0.003    0.003    0.257    0.257 {built-in method builtins.sum}
         3001    0.016    0.000    0.254    0.000 main.py:21(<genexpr>)
         3000    0.005    0.000    0.239    0.000 main.py:16(line_total)
         3000    0.234    0.000    0.234    0.000 main.py:9(find_price)
  5. Üben · Aufgabe 5 von 7

    Ordnen Sie jedem Teil einer Profilzeile seine Bedeutung zu.

  6. Denksport · Aufgabe 6 von 7

    Knobelaufgabe. Die List Comprehension behält die erlaubten Elemente. Wie oft wurde get_allowed laut Profil aufgerufen?

    import cProfile
    import pstats
    
    
    def get_allowed():
        return {"a", "b"}
    
    
    items = ["a", "b", "c", "d"] * 25
    with cProfile.Profile() as profiler:
        kept = [x for x in items if x in get_allowed()]
    
    rows = pstats.Stats(profiler).get_stats_profile().func_profiles
    print(rows["get_allowed"].ncalls)
  7. Anwenden · Aufgabe 7 von 7

    Kleine Aufgabe, auf Ihrem eigenen Rechner. Nehmen Sie ein eigenes Skript, das langsam wirkt, oder das Beispiel unten. Starten Sie python -m cProfile -s cumulative script.py und notieren Sie den teuersten Arbeitsschritt. Profilieren Sie dann mit -s tottime und benennen Sie die heiße Funktion. Korrigieren Sie sie, profilieren Sie erneut und notieren Sie ihre ncalls und tottime vorher und nachher.

    Prüfen Sie Ihr Ergebnis anhand dieser Liste

Selbst programmieren

Lesen Sie das ausgearbeitete Beispiel und lösen Sie dann die Übungen. Ihr Code läuft in Ihrem Browser oder auf Ihrem Computer und wird nie hochgeladen.

Ausgearbeitetes Beispiel

Die heiße Funktion in einem Bericht finden

report addiert 3000 Bestellungen; line_total sucht jeden Preis mit find_price, das eine Liste von 2000 Paaren durchsucht. Das Programm profiliert einen Lauf und liest die Zahlen mit get_stats_profile(), statt die ganze Tabelle auszugeben: Die Sekunden ändern sich bei jedem Lauf, Aufrufzahlen und Spitzenreiter nicht. Starten Sie es auf Ihrem Rechner und ergänzen Sie dann stats.print_stats(5), um die Tabelle selbst zu sehen.

main.py

import cProfile
import pstats
from pstats import SortKey

PRICES = [(f"item{i}", i * 0.5) for i in range(2000)]


def find_price(name: str) -> float:
    for key, price in PRICES:  # a linear search: suspicious
        if key == name:
            return price
    raise KeyError(name)


def line_total(name: str, quantity: int) -> float:
    return find_price(name) * quantity


def report(orders: list[tuple[str, int]]) -> float:
    return sum(line_total(name, quantity) for name, quantity in orders)


orders = [(f"item{i % 2000}", 1 + i % 3) for i in range(3000)]

with cProfile.Profile() as profiler:
    total = report(orders)
print(f"total: {total:.1f}")

stats = pstats.Stats(profiler).strip_dirs().sort_stats(SortKey.TIME)
# stats.print_stats(5)  # the full table; its seconds differ on every run
profile = stats.get_stats_profile()
rows = profile.func_profiles

hottest = max(rows, key=lambda name: rows[name].tottime)
print("hottest:", hottest)
print("over half of all time:", rows[hottest].tottime > profile.total_tt / 2)
for name in ("report", "line_total", "find_price"):
    print(f"{name}: {rows[name].ncalls} calls")

Ausführen mit

python main.py

Ausgabe

total: 2498500.0
hottest: find_price
over half of all time: True
report: 1 calls
line_total: 3000 calls
find_price: 3000 calls
  • find_price hat die höchste tottime: Die Schleife über PRICES ist der Ort, an dem gearbeitet wird.
  • line_total und report haben ebenfalls eine hohe cumtime, aber nur, weil find_price unter ihnen läuft.
  • find_price läuft 3000-mal und durchsucht jedes Mal bis zu 2000 Paare; ein einmal gebautes dict erspart die Suche.
  • ncalls ist in get_stats_profile() ein String, weil eine rekursive Funktion es als "15/1" meldet.

Übungen

Übung 1 von 2

Aufrufe mit einem Profil zählen

Vervollständigen Sie profile_calls(func, *args). Führen Sie func(*args) in with cProfile.Profile() as profiler: aus, nutzen Sie dann pstats.Stats(profiler).get_stats_profile() und geben Sie ein dict von jedem Funktionsnamen auf seine Aufrufzahl als int zurück. Bei einer rekursiven Funktion sieht ncalls wie "25/1" aus: Zählen Sie die erste Zahl. Starten Sie die Tests und probieren Sie es dann auf Ihrem Rechner mit eigenen Funktionen.

Diese Übung braucht Python auf Ihrem Computer (die Browser-Version kann sie nicht ausführen). Dateien und Befehle stehen unten.

Hinweise
  1. Hinweis 1

    Setzen Sie func(*args) in with cProfile.Profile() as profiler:, damit nur dieser Aufruf aufgezeichnet wird.

  2. Hinweis 2

    get_stats_profile().func_profiles bildet jeden Funktionsnamen auf ein Objekt mit dem Attribut ncalls ab, einem String.

  3. Hinweis 3

    int(row.ncalls.split("/")[0]) macht aus "3" wie aus "25/1" eine Zahl.

Eine Lösung zeigen

Ein möglicher Lösungsweg. Ihrer kann anders aussehen und trotzdem alle Prüfungen bestehen.

import cProfile
import pstats
from collections.abc import Callable


def profile_calls(func: Callable[..., object], *args: object) -> dict[str, int]:
    with cProfile.Profile() as profiler:
        func(*args)
    profile = pstats.Stats(profiler).get_stats_profile()
    return {name: int(row.ncalls.split("/")[0]) for name, row in profile.func_profiles.items()}
Auf dem eigenen Computer ausführen

Installieren Sie Python 3.14 oder neuer. Speichern Sie diese Dateien in einem Ordner, öffnen Sie dort ein Terminal und führen Sie die Befehle unten aus.

main.py

import cProfile
import pstats
from collections.abc import Callable


def profile_calls(func: Callable[..., object], *args: object) -> dict[str, int]:
    # Run func(*args) under cProfile.Profile, then return {function name: number of calls}.
    # A recursive function's ncalls looks like "15/1": count the first number.
    func(*args)
    return {}

test_main.py

from main import profile_calls


def fib(n):
    return n if n < 2 else fib(n - 1) + fib(n - 2)


def helper(x):
    return x * 2


def three_helpers():
    return helper(1) + helper(2) + helper(3)


def test_counts_calls():
    """three_helpers läuft einmal und ruft helper 3-mal auf"""
    calls = profile_calls(three_helpers)
    got = calls.get("three_helpers"), calls.get("helper")
    assert got == (1, 3), f"Ergebnis {got!r} für three_helpers und helper, erwartet (1, 3)"


def test_recursion():
    """fib(6) macht insgesamt 25 Aufrufe, gezählt aus ncalls 25/1"""
    calls = profile_calls(fib, 6)
    assert calls.get("fib") == 25, f"calls['fib'] ist {calls.get('fib')!r}, erwartet 25: Nehmen Sie die Zahl vor dem Schrägstrich"


def test_values_are_ints():
    """Jede Zahl ist ein int"""
    calls = profile_calls(three_helpers)
    bad = {name: n for name, n in calls.items() if not isinstance(n, int)}
    assert calls and not bad, f"diese Zahlen sind keine ints: {bad!r}" if bad else "das dict ist leer"

Unter macOS und Linux tippen Sie python3, wo in diesen Befehlen python steht, wie in der ersten Lektion.

Programm ausführen:

python main.py

Prüfungen ausführen (learnrun.py muss im selben Ordner liegen):

python learnrun.py test
learnrun.py herunterladen

Übung 2 von 2

Den Engpass beheben

count_known zählt die Wörter, die in einem Vokabular vorkommen, ohne auf Groß- und Kleinschreibung und Leerzeichen zu achten. Starten Sie auf Ihrem Rechner python main.py: Das nach Aufrufzahl sortierte Profil zeigt normalise mit Hunderttausenden Aufrufen. Korrigieren Sie count_known so, dass jeder Vokabular-Eintrag einmal vor der Schleife normalisiert wird und jedes Wort einmal. Das Ergebnis darf sich nicht ändern; ein Test profiliert Ihre Version und zählt die Aufrufe von normalise.

Diese Übung braucht Python auf Ihrem Computer (die Browser-Version kann sie nicht ausführen). Dateien und Befehle stehen unten.

Hinweise
  1. Hinweis 1

    Die List Comprehension im if läuft für jedes Wort erneut: Daher kommen die Aufrufe.

  2. Hinweis 2

    Bauen Sie known = {normalise(v) for v in vocabulary} einmal, vor der for-Schleife.

  3. Hinweis 3

    Dann lautet die Prüfung nur normalise(word) in known, und ein Mengen-Lookup durchsucht das Vokabular nicht.

Eine Lösung zeigen

Ein möglicher Lösungsweg. Ihrer kann anders aussehen und trotzdem alle Prüfungen bestehen.

def normalise(word: str) -> str:
    return word.strip().lower()


def count_known(words: list[str], vocabulary: list[str]) -> int:
    known = {normalise(v) for v in vocabulary}
    count = 0
    for word in words:
        if normalise(word) in known:
            count += 1
    return count


if __name__ == "__main__":
    import cProfile

    words = ["Apple", "pear ", "kiwi", "PLUM"] * 500
    vocabulary = [f"fruit{i}" for i in range(300)] + ["apple", "pear", "plum"]
    cProfile.run("print(count_known(words, vocabulary))", sort="ncalls")
Auf dem eigenen Computer ausführen

Installieren Sie Python 3.14 oder neuer. Speichern Sie diese Dateien in einem Ordner, öffnen Sie dort ein Terminal und führen Sie die Befehle unten aus.

main.py

def normalise(word: str) -> str:
    return word.strip().lower()


def count_known(words: list[str], vocabulary: list[str]) -> int:
    count = 0
    for word in words:
        if normalise(word) in [normalise(v) for v in vocabulary]:
            count += 1
    return count


if __name__ == "__main__":
    import cProfile

    words = ["Apple", "pear ", "kiwi", "PLUM"] * 500
    vocabulary = [f"fruit{i}" for i in range(300)] + ["apple", "pear", "plum"]
    cProfile.run("print(count_known(words, vocabulary))", sort="ncalls")

test_main.py

import cProfile
import pstats

from main import count_known

WORDS = ["Apple", "pear ", "kiwi", "PLUM"] * 50
VOCABULARY = [f"fruit{i}" for i in range(30)] + ["apple", " Pear", "plum"]


def normalise_calls(words, vocabulary):
    with cProfile.Profile() as profiler:
        result = count_known(words, vocabulary)
    rows = pstats.Stats(profiler).get_stats_profile().func_profiles
    return result, int(rows["normalise"].ncalls) if "normalise" in rows else 0


def test_same_answer():
    """150 der 200 Wörter sind bekannt"""
    got = count_known(WORDS, VOCABULARY)
    assert got == 150, f"count_known lieferte {got!r}, erwartet 150"


def test_normalises_each_word_once():
    """normalise läuft einmal pro Wort und einmal pro Vokabular-Eintrag"""
    result, calls = normalise_calls(WORDS, VOCABULARY)
    expected = len(WORDS) + len(VOCABULARY)
    assert calls == expected, f"normalise wurde {calls}-mal aufgerufen, erwartet {expected}: Normalisieren Sie das Vokabular einmal, vor der Schleife"


def test_empty_words():
    """Keine Wörter: das Ergebnis ist 0"""
    got = count_known([], VOCABULARY)
    assert got == 0, f"count_known([], ...) lieferte {got!r}, erwartet 0"

Unter macOS und Linux tippen Sie python3, wo in diesen Befehlen python steht, wie in der ersten Lektion.

Programm ausführen:

python main.py

Prüfungen ausführen (learnrun.py muss im selben Ordner liegen):

python learnrun.py test
learnrun.py herunterladen

Häufige Fehler

Ein Sortierschlüssel, den es nicht gibt

import cProfile
import pstats

with cProfile.Profile() as profiler:
    sum(range(1000))

pstats.Stats(profiler).sort_stats("speed").print_stats(5)

Was Python ausgibt

KeyError: 'speed'

Warum, und die Lösung

sort_stats akzeptiert nur die dokumentierten Schlüssel wie "calls", "cumulative", "tottime" und "name" oder ihre SortKey-Mitglieder. Eine Abkürzung klappt nur, wenn sie eindeutig ist: "cum" passt zu "cumulative" und "cumtime" und scheitert genauso. Nehmen Sie lieber SortKey.CUMULATIVE: mypy bemerkt ein falsch geschriebenes Enum-Mitglied, einen falsch geschriebenen String nicht.

String-Schlüssel und Enum-Namen verwechseln

import cProfile
import pstats
from pstats import SortKey

with cProfile.Profile() as profiler:
    sum(range(1000))

pstats.Stats(profiler).sort_stats(SortKey.TOTTIME).print_stats(5)

Was Python ausgibt

AttributeError: type object 'SortKey' has no attribute 'TOTTIME'

Warum, und die Lösung

Die Spalte heißt tottime, und der String "tottime" ist ein gültiger Schlüssel, aber das Enum-Mitglied für interne Zeit heißt SortKey.TIME. Ebenso hat "cumtime" kein eigenes Mitglied: Nehmen Sie SortKey.CUMULATIVE.

Python im Browser: Pyodide 314.0.7, MPL-2.0. Lizenz und Quellcode

Abschlussquiz

5 Fragen, ohne Hinweise. Ab 80 % ist die Lektion abgeschlossen.

Erledigen Sie zuerst alle Aufgaben oben, um das Abschlussquiz freizuschalten.

Problem melden

Etwas ist falsch oder unklar? Beschreiben Sie es kurz, dann wird es geprüft und korrigiert.

#

Mindestens 20 Zeichen.

Nur, wenn Sie eine Antwort wünschen.

Kernideen

Ein Profil zählt jeden Aufruf

cProfile zeichnet jeden Funktionsaufruf und jede Rückkehr auf, samt Dauer. Ein ganzes Skript profilieren Sie mit python -m cProfile -s cumulative script.py, einen String mit cProfile.run("main()"), einen Block mit with cProfile.Profile() as profiler:. Der Profiler bremst Python-Code stärker als C-Code; nutzen Sie ihn, um herauszufinden, wohin die Zeit geht, und timeit, um zu messen, wie schnell etwas ist. cProfile.run führt seinen String im Modul __main__ aus, die Namen darin müssen dort existieren.

Die Spalten lesen

ncalls ist die Zahl der Aufrufe; 15/1 heißt 15 Aufrufe, davon 1 nicht rekursiv. tottime ist die Zeit im eigenen Code der Funktion, ohne die Funktionen, die sie aufruft. cumtime schließt alles Aufgerufene ein. Hohe cumtime bei niedriger tottime heißt: „Die Zeit steckt unter mir“; wo tottime hoch ist, passiert die Arbeit. Eine überraschende Aufrufzahl, etwa eine Hilfsfunktion, die in einer Schleife in der Schleife läuft, zeigt oft direkt auf das Problem.

Sortieren und kürzen mit pstats

pstats.Stats(profiler) macht aus den Daten einen Bericht. strip_dirs() kürzt Dateipfade, sort_stats(SortKey.CUMULATIVE) oder sort_stats("tottime") legt die Reihenfolge fest, und print_stats(10) gibt nur die ersten zehn Zeilen aus. Sortieren Sie nach kumulativer Zeit, um den teuren Arbeitsschritt zu sehen, dann nach interner Zeit, um die heiße Schleife zu finden. get_stats_profile() liefert dieselben Zahlen als Objekte, sodass Skript oder Test die ncalls einer Funktion lesen, statt Text zu zerlegen.

Quellen

Zuletzt geprüft am 29. September 2026