Observability: Traces und Logs

Track KI · M5 Betrieb, Baustein 02 · ca. 55 Min. plus Projektaufgabe

Worum es geht

Eine LLM-Anwendung muss sich erklären können, wenn sie langsam oder falsch ist. Dafür machst du jeden Schritt sichtbar: wie lange hat das Retrieval gedauert, wie lange der Modellaufruf, und welche Log-Zeilen gehören zu genau dieser Anfrage. Das heißt Observability (Beobachtbarkeit), in der Quelle “Tracing und Logs”.

Was du aus Teil 1 brauchst: ein Image ist lesbar und unveränderlich, und ein Schlüssel darf nie hinein. Das gilt hier sinngemäß auch für Spans und Logs (Schritt 2). Die Grundbegriffe stehen in konzepte/09b (die drei Signale Logs, Metriken, Traces und die Trace-ID, Schritt 4) und in ki/04 (strukturierte Logs mit Korrelations-ID). Das wiederholen wir nicht. Hier wendest du es auf LLM-Anwendungen an: welche Schritte einer RAG-Anfrage einen Span bekommen, wie du den teuersten Schritt findest und wie du zu einem langsamen Trace die passenden Log-Zeilen findest.

Im Browser sind Spans und Logs Listen von Dictionaries, die du auswertest. OpenTelemetry gibt es hier nicht, die Zeiten sind vorgegeben, nicht gemessen. Am Ende steht die Projektaufgabe (lokal): das Image bauen und einen Trace ansehen.

Zeitplan ehrlich: etwa 20 Minuten Lesen, 35 Minuten für die drei Übungen. Die Projektaufgabe kommt obendrauf.

Von JS/TS her gedacht

Idee JS/TS (Node) Python-Projekt
Span um einen Schritt tracer.startActiveSpan("retrieval", span => { ... span.end() }) with tracer.start_as_current_span("retrieval"):
Strukturierter Log mit Anfrage-ID pino mit AsyncLocalStorage logging mit ContextVar (ki/04)
Attribute am Span span.setAttribute("tokens_ein", 812) span.set_attribute("tokens_ein", 812)
Eindeutige ID UUID je Anfrage Trace-ID je Anfrage, Span-ID je Schritt

Der Unterschied zu einem normalen Web-Dienst: Bei einem Modellaufruf reicht Dauer und Status nicht, am Span hängen auch Tokens und die Anzahl der Treffer. Und Span-IDs sind nur innerhalb eines Traces eindeutig, ein Detail, das beim Auswerten über viele Anfragen zählt.

Konzept

Schritt 1: Spans als Daten

Jetzt Observability. Ein Span ist ein Zeitabschnitt eines Schrittes mit Anfang, Ende und Elternteil. Alle Spans einer Anfrage zusammen sind ein Trace (ein Baum). Die Quelle zeigt es mit OpenTelemetry (nicht im Browser ausführbar, das Paket gibt es hier nicht):

from opentelemetry import trace

tracer = trace.get_tracer(__name__)

with tracer.start_as_current_span("rag_anfrage") as span:
    span.set_attribute("frage", frage[:100])
    with tracer.start_as_current_span("retrieval"):
        chunks = hybrid_search(frage)
    with tracer.start_as_current_span("llm_aufruf"):
        antwort = erzeuge_antwort(frage, chunks)

Der Aufbau dahinter ist reine Datenstruktur, und die baust du im Browser nach. Ein Span ist ein Dictionary. Die Zeiten sind in Millisekunden und hier vorgegeben, nicht gemessen (Zeitmessung im Browser ist unzuverlässig):

Die Wurzel ist der Span ohne Elternteil (parent ist None). Jetzt die Frage der Quelle: welcher Schritt ist am teuersten? Die Gesamtdauer täuscht, denn die Wurzel ist immer am längsten, und retrieval enthält embedding und vektorsuche. Aussagekräftig ist die Eigenzeit (self time): die Dauer eines Spans minus die Dauer seiner direkten Kinder. Sie sagt, wie lange der Schritt selbst gearbeitet hat und nicht seine Teilschritte:

rag_anfrage hat 1450 ms gesamt, aber nur 50 ms Eigenzeit. retrieval hat 360 ms gesamt und 15 ms Eigenzeit, die Zeit steckt in vektorsuche (260 ms). Der teuerste Schritt ist llm_aufruf mit 900 ms. Zwei Hinweise: Laufen Kinder parallel, kann ihre Summe größer sein als die Elterndauer, die Eigenzeit wird dann negativ. In dieser Lektion laufen alle Kinder nacheinander. Und: Bei einer Fehlersuche willst du oft den Teilschritt sehen, nicht den Mittelwert. Die Quelle fragt auch nach dem Durchschnitt über viele Anfragen. Das ist dieselbe Rechnung, nur über mehrere Traces gemittelt (unten).

Der Durchschnitt über viele Anfragen. Die Quelle fragt auch danach, wo im Schnitt die Zeit bleibt. Du rechnest die Eigenzeit je Trace und mittelst sie je Schrittname. Eine Falle dabei: Span-IDs sind nur innerhalb eines Traces eindeutig. Jeder Trace darf seinen Wurzel-Span s1 nennen. Wirfst du zwei Traces in eine Liste und baust ein dict nach ID, überschreiben sich die Einträge:

Ausgabe: {'s1': 40, 's2': 300, 's3': 660}, dann {'s1': 120, 's2': 200, 's3': 2680}, dann {'s1': -2760, 's2': 200, 's3': 2680}. Die ersten beiden Zeilen stimmen. In der dritten ist die Eigenzeit von s1 negativ, weil die Dauer aus dem zweiten Trace und die Kinder aus beiden Traces gemischt wurden. Richtig ist: erst je Trace rechnen, dann mitteln. Der Mittelwert der Eigenzeit von llm_aufruf ist (660 + 2680) / 2 = 1670, der von retrieval (300 + 200) / 2 = 250 und der von rag_anfrage (40 + 120) / 2 = 80. Das schreibst du in Übung 3.

Schritt 2: Was an einem LLM-Span zusätzlich hängt

Bei einem normalen Web-Dienst reichen Dauer und Status. Bei einem Modellaufruf willst du am Span mehr sehen (Quelle: Langfuse zeigt Prompt, Antwort und Tokenkosten pro Span in einer Oberfläche): zum Beispiel Modellname, Anzahl Eingabe- und Ausgabe-Tokens, bei Retrieval die Zahl der Treffer. Mit OpenTelemetry sind das Attribute (span.set_attribute("tokens_ein", 812)). Drei Regeln (allgemeines Fachwissen):

  • Keine Schlüssel in Attributen, wie im Log.
  • Prompts und Antworten enthalten oft personenbezogene Daten. Was du in einem Trace speicherst, liegt in einem Werkzeug, auf das mehr Leute Zugriff haben als auf die Datenbank. Kürze oder maskiere (die Quelle schneidet die Frage im Beispiel mit frage[:100] ab).
  • Metriken sind anders: Nutzer-ID oder Anfrage-ID gehören nicht in ein Metrik-Label (Kardinalität, siehe konzepte/09b), aber sehr wohl in einen Trace oder Log.

Die Quelle sagt es so: Observability ist strukturiertes Logging aus M0, nur mit Zeitmessung und Verschachtelung dazu.

Schritt 3: Logs und Traces zusammenführen

Der Trace sagt, wo die Zeit blieb. Der Log sagt, was dort passiert ist (Retry, Rate Limit, Fehler). Zusammen sind sie stark, wenn jede Log-Zeile die Trace-ID und die Span-ID trägt. Die Trace-ID ist nichts Neues: Es ist die Korrelations-ID aus ki/04, nur dass sie jetzt auch an den Spans hängt. Bei OpenTelemetry liest du sie im Python-Code aus dem aktuellen Span (nicht im Browser ausführbar, nicht ausgeführt, bitte prüfen):

ctx = trace.get_current_span().get_span_context()
trace_id = format(ctx.trace_id, "032x")   # als 32 Hex-Zeichen
span_id = format(ctx.span_id, "016x")     # als 16 Hex-Zeichen

Im Browser bauen wir dieselbe Verbindung mit Dictionaries: Jeder Span bekommt ein Feld trace_id, jede Log-Zeile trace_id und span_id. Zwei Traces, t-17 aus dem Beispiel oben und ein langsamer t-18:

Dieses Muster brauchst du ständig: Du siehst im Trace-Werkzeug, dass t-18 5200 ms gedauert hat, filterst die Log-Zeilen nach seiner Trace-ID, sortierst nach Zeit und siehst, dass im Span llm_aufruf ein Rate Limit wartete. Ohne gemeinsame ID müsstest du Zeitstempel raten.

Falle

  1. Gesamtdauer statt Eigenzeit lesen. Die Wurzel gewinnt immer. Frage nach der Eigenzeit, sonst schaust du am falschen Schritt.
  2. Trace und Log ohne gemeinsame ID. Dann sind beide Daten da, aber nicht zusammenzubringen.
  3. Span-IDs über Traces hinweg gemischt. IDs sind nur innerhalb eines Traces eindeutig. Wer Spans mehrerer Traces in ein dict nach ID legt, überschreibt Einträge und bekommt negative Eigenzeiten. Nimm (trace_id, id) als Schlüssel.

Übungen

Übung 1: Den teuersten Schritt finden (mittel, ca. 12 Min.)

Ein Agent hat einen Trace erzeugt (Zeiten in ms, vorgegeben). Schreibe teuerster_schritt(spans): Sie gibt die id des Spans mit der größten Eigenzeit zurück (Dauer minus Dauer der direkten Kinder, wie in Schritt 1). Die Spans stehen in beliebiger Reihenfolge, Kinder können vor ihren Eltern stehen. Alle Kinder laufen nacheinander. Es gibt nie Gleichstand. Im Beispiel unten ist die Antwort "a4".

Zwei naheliegende Antworten sind falsch: der Span mit der größten Gesamtdauer und der Span mit der größten Gesamtdauer unter allen außer der Wurzel. Was musst du für jeden Span zuerst ausrechnen, und welche Spans zählen dabei als seine Kinder?

spans = [
    {"id": "a1", "parent": None, "name": "agent_lauf",  "start": 0,    "ende": 2000},
    {"id": "a2", "parent": "a1", "name": "plan",        "start": 10,   "ende": 400},
    {"id": "a3", "parent": "a1", "name": "tool_suche",  "start": 400,  "ende": 1500},
    {"id": "a4", "parent": "a3", "name": "http_abruf",  "start": 410,  "ende": 1450},
    {"id": "a5", "parent": "a1", "name": "tool_rechnen", "start": 1500, "ende": 1550},
    {"id": "a6", "parent": "a1", "name": "antwort",     "start": 1560, "ende": 1980},
]

def teuerster_schritt(spans):
    dauer = {s["id"]: s["ende"] - s["start"] for s in spans}
    kinder_summe = {s["id"]: 0 for s in spans}
    for s in spans:
        if s["parent"] is not None:
            kinder_summe[s["parent"]] += dauer[s["id"]]
    eigenzeit = {i: dauer[i] - kinder_summe[i] for i in dauer}
    return max(eigenzeit, key=eigenzeit.get)

print(teuerster_schritt(spans))
teuerster_schritt

Übung 2: Die Warnungen des langsamsten Traces (mittel bis schwer, ca. 14 Min.)

Beim Kunden meldet jemand: “Manche Anfragen sind sehr langsam.” Du hast Spans und Logs von drei Traces. Schreibe fehler_im_langsamsten_trace(spans, logs):

  1. Der langsamste Trace ist der mit der längsten Dauer seines Wurzel-Spans (parent ist None). Es gibt nie Gleichstand.
  2. Nimm nur die Log-Zeilen dieses Traces mit Level "WARNING" oder "ERROR" (andere Level: "DEBUG", "INFO").
  3. Sortiere sie nach ts aufsteigend.
  4. Gib eine Liste von Tupeln (span_name, msg) zurück. Der Name kommt über span_id aus den Spans. Hat eine Zeile keine span_id (Wert None) oder kennt kein Span sie, ist der Name "(ohne Span)".

Im Beispiel unten ist das Ergebnis [("llm_aufruf", "Rate Limit 429"), ("(ohne Span)", "Fehler beim Zusammenfassen")].

Zerlege es in vier kleine Schritte: Trace finden, Zeilen filtern, sortieren, Namen nachschlagen. Für das Nachschlagen eignet sich ein Dictionary von Span-Id zu Name. Bei einem Level-Vergleich fragst du besser nach der Zugehörigkeit zu einer Menge als nach Größer oder Kleiner auf Texten: Was sagt "WARNING" > "ERROR" über die Alphabet-Reihenfolge?

spans = [
    {"id": "p1", "parent": None, "name": "zusammenfassung", "start": 0,   "ende": 900,  "trace_id": "t-1"},
    {"id": "p2", "parent": "p1", "name": "llm_aufruf",      "start": 50,  "ende": 880,  "trace_id": "t-1"},
    {"id": "q1", "parent": None, "name": "zusammenfassung", "start": 0,   "ende": 4100, "trace_id": "t-2"},
    {"id": "q2", "parent": "q1", "name": "llm_aufruf",      "start": 60,  "ende": 4090, "trace_id": "t-2"},
    {"id": "r1", "parent": None, "name": "zusammenfassung", "start": 0,   "ende": 1200, "trace_id": "t-3"},
]
logs = [
    {"ts": 3000, "level": "ERROR",   "trace_id": "t-2", "span_id": None, "msg": "Fehler beim Zusammenfassen"},
    {"ts": 100,  "level": "INFO",    "trace_id": "t-2", "span_id": "q2", "msg": "Modellaufruf gestartet"},
    {"ts": 500,  "level": "WARNING", "trace_id": "t-1", "span_id": "p2", "msg": "Antwort langsam"},
    {"ts": 1500, "level": "WARNING", "trace_id": "t-2", "span_id": "q2", "msg": "Rate Limit 429"},
    {"ts": 700,  "level": "ERROR",   "trace_id": "t-3", "span_id": "r1", "msg": "Dokument leer"},
]

def fehler_im_langsamsten_trace(spans, logs):
    wurzeln = [s for s in spans if s["parent"] is None]
    langsam = max(wurzeln, key=lambda s: s["ende"] - s["start"])["trace_id"]
    name_von = {s["id"]: s["name"] for s in spans}
    treffer = [z for z in logs
               if z["trace_id"] == langsam and z["level"] in ("WARNING", "ERROR")]
    treffer.sort(key=lambda z: z["ts"])
    return [(name_von.get(z["span_id"], "(ohne Span)"), z["msg"]) for z in treffer]

print(fehler_im_langsamsten_trace(spans, logs))
fehler_im_langsamsten_trace

Übung 3: Die mittlere Eigenzeit je Schritt (mittel, ca. 12 Min.)

Du hast Spans aus mehreren Traces in einer Liste. Jeder Span hat zusätzlich das Feld trace_id. Schreibe mittlere_eigenzeit(spans):

  1. Die Eigenzeit eines Spans ist seine Dauer minus die Dauer seiner direkten Kinder. Kinder sind die Spans desselben Traces, deren parent die id des Spans ist. Span-IDs wiederholen sich zwischen Traces.
  2. Das Ergebnis ist ein dict {name: Mittelwert der Eigenzeit}. Gemittelt wird über alle Spans mit diesem Namen (kommt ein Name in einem Trace mehrfach vor, zählt jeder Span einzeln).
  3. Die Spans stehen in beliebiger Reihenfolge. Eine leere Liste ergibt {}.

Beispiel mit den beiden Traces aus Schritt 1: {"rag_anfrage": 80.0, "retrieval": 250.0, "llm_aufruf": 1670.0}.

Was ist ein eindeutiger Schlüssel für einen Span, wenn die id allein es nicht ist? Und was musst du je Name sammeln, damit der Mittelwert über Spans und nicht über Traces gebildet wird?

def mittlere_eigenzeit(spans):
    dauer = {(s["trace_id"], s["id"]): s["ende"] - s["start"] for s in spans}
    kinder = {schluessel: 0 for schluessel in dauer}
    for s in spans:
        if s["parent"] is not None:
            kinder[(s["trace_id"], s["parent"])] += dauer[(s["trace_id"], s["id"])]
    je_name = {}
    for s in spans:
        k = (s["trace_id"], s["id"])
        je_name.setdefault(s["name"], []).append(dauer[k] - kinder[k])
    return {name: sum(werte) / len(werte) for name, werte in je_name.items()}
mittlere_eigenzeit

Projektaufgabe: Image bauen und Trace ansehen (lokal, nicht im Browser)

Das sind die Übungen der Quelle (Docker aus Teil 1, Spans aus diesem Teil): Das Lernlabor-Projekt aus M0 containerisieren, das Image zweimal bauen und die Paketversionen vergleichen (Baustein 01), und einen mehrstufigen Ablauf mit verschachtelten Spans versehen und den teuersten Schritt ablesen (Baustein 02). Beides läuft lokal im Lernlabor, nicht im Browser. Es wird nichts installiert, kein Docker von uns gestartet und kein Schlüssel in eine Datei geschrieben. Das Skript lernlabor/uebung/ki/ki_16_docker_bauen.py enthält die Anleitung und den Rahmen:

cd lernlabor && uv run python uebung/ki/ki_16_docker_bauen.py

Was das Skript tut, in Reihenfolge:

  1. Trockenlauf (Standard). Es prüft, ob das Programm docker vorhanden ist und ob der Docker-Dienst antwortet. Fehlt etwas, meldet es verständlich, was fehlt, und läuft weiter. Es installiert und startet nichts.
  2. Es liest lernlabor/Dockerfile und lässt den Checker aus Teil 1 (Schritt 3) darüber laufen. Gibt es noch kein Dockerfile, prüft es stattdessen eine Vorlage, die es im Skript mitbringt, und sagt dir, dass du dein eigenes anlegst. Die Vorlage ist nicht gebaut und nicht getestet (bitte prüfen).
  3. Es zeigt die Docker-Befehle zum zweimaligen Bauen und zum Auslesen der Paketversionen, führt sie aber nur mit dem Schalter --bauen aus (das machst du selbst, wenn Docker läuft).
  4. Es spielt einen kleinen Trace mit Spans durch (reines Python, simulierte Zeiten, ohne opentelemetry) und zeigt den teuersten Schritt. Deine Aufgabe ist, denselben Aufbau im RAG-System aus M2 mit echten Zeitmessungen einzubauen. Das Paket opentelemetry gehört nicht zur pyproject.toml des Lernlabors: Frag erst nach, bevor du es mit uv add installierst. Die Alternative ohne Paket ist ein kleiner eigener span-Kontextmanager, wie er im Skript steht.

Fertig, wenn:

  • Dein lernlabor/Dockerfile baut (im Ordner lernlabor: docker build -t lernlabor:a .) und lint meldet keinen Befund.
  • Du das Image zweimal gebaut und die Paketversionen verglichen hast, und du erklären kannst, warum sie mit --frozen identisch sind.
  • Dein Image enthält keinen Schlüssel: Die .env steht in der .dockerignore, Schlüssel kommen über --env-file oder die Umgebung zur Laufzeit.
  • Du ein Trace-Ergebnis für mindestens drei verschachtelte Schritte hast und für jeden die Eigenzeit nennst.

Hinweise, die in der Quelle nicht stehen (allgemeines Fachwissen, nicht im Container ausgeführt, bitte prüfen): Das Lernlabor ist ein Paket mit uv_build und verlangt Python ab 3.13 (requires-python in pyproject.toml), das Basis-Image muss also python:3.13-slim oder neuer sein, nicht 3.12 wie im Beispiel der Quelle. Ein uv sync direkt nach dem Kopieren von pyproject.toml und uv.lock scheitert, weil der Quellcode des Pakets noch fehlt (an einem Testprojekt mit uv 0.12.10 ausgeführt, nicht im Container). Dafür gibt es uv sync --frozen --no-dev --no-install-project im ersten Schritt (die Option existiert in der installierten uv-Version) und einen zweiten Aufruf von uv sync --frozen --no-dev, nachdem src/ kopiert ist. Das Paket verlangt außerdem README.md (steht in pyproject.toml).

Selbstcheck:

Merksatz

Observability ist strukturiertes Logging aus M0, nur mit Zeitmessung, Verschachtelung und einer gemeinsamen ID dazu (Quelle): Die Eigenzeit zeigt, wo gearbeitet wurde, die Trace-ID verbindet Span und Log, und IDs gelten nur innerhalb eines Traces.

Prüfstein

Der Kunde sagt: “Gestern Nachmittag war der Chatbot bei manchen Anfragen sehr langsam.” Du hast Traces und JSON-Logs, jede Log-Zeile trägt eine Trace-ID. Beschreibe in vier Schritten, wie du den Grund findest, und sage, welche Zahl du je Span ansiehst (Gesamtdauer oder Eigenzeit) und warum.

Quelle: quellen/kursbuch-lerninhalte.md, Modul M5, Baustein “02 Observability: Tracing und Logs” (Warum, Kernidee, Stolperfalle, Merksatz, Übung). Aus der Quelle stammen: der OpenTelemetry-Code mit verschachtelten Spans und set_attribute("frage", frage[:100]), die Aussage zu Langfuse, der Merksatz und die Übung zu Spans (teuerster Schritt); die Übung zum zweimaligen Bauen des Images (Baustein 01) steht in der Projektaufgabe. Über die Quelle hinaus (allgemeines Fachwissen, soweit nicht anders vermerkt; Docker, OpenTelemetry und uv wurden nicht ausgeführt, bitte prüfen): die Eigenzeit eines Spans, der Durchschnitt über mehrere Traces und die Eindeutigkeit von Span-IDs nur innerhalb eines Traces, Hinweise zu Attributen und personenbezogenen Daten, Trace-ID und Span-ID als Hex-Zeichen, der Hinweis zu uv sync --no-install-project. Alle Zeiten, Spans und Logs sind erfunden.