Asyncio-ContextVar-Memory-Leak: Wie Sentrys Dedupe-Integration jeden fehlgeschlagenen Scheduler-Tick zusammenkettete

Ein asyncio-ContextVar-Memory-Leak gehört zu der Sorte Produktions-Bugs, die zwei Schichten unter der Stelle sitzen, an der man zuerst nachsieht. Der Scheduler auf unserem Staging-Host war auf 5,4 GB residenten Speicher angewachsen, bevor es uns auffiel. Die Logzeile, die ihn verraten hätte, lag tief in einer Sentry-Integration vergraben, die standardmässig aktiv ist. Die letzten vier git log-Einträge auf der Datei waren unverdächtig. Das Symptom war langsam, die Ursache unsichtbar, der Fix ein einzelner Call-Wrapper.

Das ist die Aufzeichnung des Lecks, das wir im Automation-Scheduler hinter Wield aufgespürt haben — unserem Schweizer Recruiting-Intelligence-Produkt auf einem Python-Backend, das jede Minute cron-artige Agent-Ticks ausführt — und die generelle Lehre, die wir daraus mitgenommen haben: Ein langlebiger Coroutine-Loop ist kein sicherer Ort für alles, was Pythons contextvars berührt, und ein direktes await einer Coroutine aus einem solchen Loop ist für alles, was fehlschlagen kann, ein stiller Default-Fehler.

Das Symptom: 0,75 MB pro Tick, reproduzierbar

Der Scheduler tickt jede Minute. Bei jedem Tick liest er einen Stapel fälliger Automationsjobs aus Postgres, reiht sie ein und geht wieder schlafen. An einem gesunden Tag tut er sichtbar nichts — ein Tick dauert wenige Millisekunden, und die einzige Spur ist ein Zähler auf dem Prometheus-Endpunkt. Am Tag, als es uns auffiel, zählte der Zähler immer noch exakt einen pro Minute, jeder Job wurde sauber eingereiht, jeder Worker verarbeitete sauber, und das Resident-Set des Schedulers war bei 5,4 GB.

Ein Prozess-Neustart brachte den Speicher auf 90 MB zurück. Eine Stunde später waren es 134 MB. Einen Tag später wieder über ein Gigabyte. Das Wachstum war linear, reproduzierbar und hatte genau die Form eines Lecks, das mit der Zahl der Loop-Iterationen skaliert, nicht mit dem Request-Volumen oder Datenvolumen. Auf Staging war die Steigung 942 KB pro Tick — eine Zahl, die wir nur hatten, weil tracemalloc.take_snapshot in unsere Telemetrie-Pipeline uns einen Minuten-Diff lieferte. Auf dem Produktions-Host, geteilt mit Acurio, war die Steigung geringer, aber nicht null, und über mehrere redeployfreie Wochen war sie trotzdem die dominante Memory-Story der Maschine.

Die Jobs selbst waren in Ordnung. Worker starteten sauber durch, DB-Sessions schlossen, das Agent-SDK gab seine HTTP-Verbindungen frei. Das Leck lag ausschliesslich im Scheduler, und es war der Scheduler-Loop selbst — nicht ein Job, den er eingereiht hat — der etwas festhielt.

Die erste Hypothese, die wir ausgeschlossen haben

Der Scheduler macht pro Tick einen Call, der der naheliegende Verdächtige wäre: Er öffnet eine SQLAlchemy-Session, liest ein paar Zeilen und schliesst sie in einem finally. Der erste Instinkt — und die ersten dreissig Minuten der Untersuchung — war, dass die Session irgendwo gehalten wurde, vermutlich über einen hängengebliebenen Verweis auf eine nicht abgelöste Modell-Instanz. objgraph.show_backrefs auf den Top-Halter widersprach. Die Session wurde geschlossen. Die Row-Objekte waren im nächsten GC-Durchlauf weg. Was sich ansammelte, war kein SQLAlchemy-State.

Die zweite Hypothese war, dass unser Logging-Stack formatierte Nachrichten puffert. Wir loggen für Loki nach stdout, und der Scheduler ist redselig. logging.getLogger().handlers[0].stream zeigte auf ein nacktes sys.stderr; kein Buffering, kein In-Memory-Handler. Nichts in Standard-Logging hält vergangene Records fest.

Die dritte Hypothese war die richtige, und sie brauchte das Glück von tracemalloc, um gefunden zu werden: Die am meisten gehaltenen Objekte in jedem Diff waren TracebackType und die Frame-Objekte, die sie transitiv am Leben hielten. Der Scheduler sammelte Exception-Tracebacks an, einen pro fehlgeschlagenem Tick. Was seltsam war, weil der Scheduler Exceptions eigentlich schlucken und weitermachen sollte.

Die wahre Ursache: Sentrys Dedupe-Integration im falschen Kontext

Sentrys Python-SDK liefert standardmässig eine Integration namens DedupeIntegration. Ihre Aufgabe ist bescheiden und nützlich: Sie unterdrückt doppelte Reports, wenn dieselbe Exception innerhalb eines Requests durch zwei Capture-Punkte sprudelt. Dafür hält sie eine Referenz auf die zuletzt erfasste Exception in einer ContextVar und verwirft den nächsten Report, wenn das Exception-Objekt (oder die Kette) dieselbe ist. Die Referenz ist per-Context, was für einen Web-Request die richtige Einheit ist: Jeder eingehende Request läuft in seinem eigenen asyncio.Task mit eigener Kopie des Kontexts, sodass eine dedupe-Exception eines Requests nie in einen anderen hineinblutet.

Der Scheduler ist aber kein Web-Request. Er ist ein einziger while not stop.is_set()-Loop, der im Haupt-Task läuft. Jeder Tick läuft im selben Kontext wie jeder andere Tick. Als ein Tick fehlschlug — einer unserer Microsoft-365-Agenten scheiterte bei jedem Tick mit einem 401, weil ein Token aus dem Sync gelaufen war, eine Geschichte für eine andere Woche — erfasste Sentry die Exception und schrieb das Exception-Objekt in seine Dedupe-ContextVar. Der nächste Tick sah diese ContextVar immer noch gefüllt. Was für sich allein eine kleine, begrenzte Kostenstelle gewesen wäre: ein Exception-Objekt, pro Tick ersetzt, nichts weiter.

Das Leck entstand aus einer Eigenheit dessen, was diese gespeicherte Exception transitiv alles hält. Für eingebaute Exception-Subklassen ist die Referenz stark, nicht schwach — die Dedupe-Integration kann hier kein WeakValueDictionary nutzen, weil viele BaseException-Subklassen keine Weak References unterstützen. Eine starke Referenz auf die Exception hält ihr __traceback__ am Leben. Der Traceback hält jeden Frame auf dem Fehlerpfad am Leben. Jeder Frame hält seine lokalen Variablen am Leben. Für den M365-Tick, der scheiterte, waren unter diesen lokalen Variablen das httpx.Response-Objekt, das den httpx.AsyncClient hielt, der den TLS-Kontext hielt, der den SSL-Session-Cache hielt, der die Connection-Pool-Einträge hielt. Die DB-Session, die den Tick eröffnet hatte, war auch dabei. Grössenordnung: rund 900 KB pro fehlgeschlagenem Tick, transitiv über einen ContextVar-Eintrag gehalten.

Auch das wäre noch kein Leck gewesen, wenn der ContextVar-Eintrag im nächsten Tick sauber ersetzt worden wäre. Die Zutat, die aus einer begrenzten Retention eine wachsende machte, war asyncio.to_thread. Der Scheduler verlagert den eigentlichen Tick-Body in einen Worker-Thread — der blockierende SQLAlchemy-Treiber ist auf einem Thread in Ordnung, auf dem Main-Loop unangenehm — und asyncio.to_thread kopiert den aktuellen Kontext, damit contextvars.copy_context() genutzt werden kann, um Kontext in den Thread-Frame zu propagieren. Diese Kopie ist ein Snapshot. Sie hält eine Referenz auf das, was zum Zeitpunkt der Kopie in der ContextVar stand. Der Fehler des nächsten Ticks lief in einen Kontext hinein, der bereits die vorige Exception enthielt, erfasste eine neue, und jetzt lief der Traceback der neuen Exception über einen Frame, dessen lokale Variablen die kopierte Kontext-Instanz des vorherigen Ticks enthielten, die die vorherige Exception enthielt, die ihren Traceback enthielt, der den Frame des Ticks davor enthielt, der eine Kopie des Kontexts des Ticks davor enthielt, und so weiter die Kette hinunter. Jeder fehlgeschlagene Tick fügte ein Glied hinzu. Der Scheduler leckte die gesamte Fehlerhistorie durch eine Kette von Kontext-Kopien, die sich in Exception-Tracebacks versteckten.

Von aussen war das deshalb so schwer zu sehen, weil jedes Glied in der Kette wie eine legitime Einzelreferenz aussah. Sentry hielt eine Exception. Die Exception hielt einen Traceback. Der Traceback hielt einen Frame. Der Frame hielt einen Kontext. Der Kontext hielt eine ContextVar mit einem Eintrag. Der Eintrag war eine Exception. Kein Zyklus, kein verdächtiger Container, keine offensichtliche Retention — nur eine Kette einzeln gehaltener starker Referenzen, die durch den geteilten Loop-Kontext zufällig wieder in sich selbst zurücklief.

Der Fix: ein frischer Task pro Iteration

Der Einzeiler-Fix ist, jeden Tick in seinem eigenen asyncio.Task auszuführen:

# Vorher
n = await tick(db=db)

# Nachher — frische Kontextkopie pro Tick
n = await asyncio.create_task(tick(db=db))

asyncio.create_task erzeugt einen Task mit einer eigenen Kopie des aktuellen Kontexts via contextvars.copy_context. Die ContextVar-Writes des Tasks propagieren nicht zurück in den Elternkontext des Loops. Wenn der Task fertig ist, wird sein Kontext verworfen. Die Dedupe-ContextVar für diesen Tick stirbt mit dem Task, der sie besass. Der nächste Tick startet aus dem unberührten Loop-Kontext heraus, der nie eine Exception-Referenz enthielt. Reproduziert im Staging-Image: 942 KB pro Tick Wachstum vorher, flach danach. Derselbe Fix ging mit derselben Zwei-Zeilen-Begründung in den Worker-Loop.

Drei Dinge, die an diesem Fix auffallen.

Er handelt nicht von Sentry. Jede Bibliothek, die aus einem Exception-Handler in eine ContextVar schreibt, verhält sich identisch. OpenTelemetrys baggage würde es. Ein selbstgebauter "Last-Error"-Cache würde es. Das Leck liegt in der Form des Loops, nicht in Sentrys Integration. Die Dedupe-Integration tut genau das, was draufsteht; der Loop gibt ihr nur die falsche Lebensdauer, um darin korrekt zu sein.

Er handelt nicht von to_thread. Wir haben die Kette nur bemerkt, weil to_thread die Kontextkopie sichtbar macht — der Thread hält eine Referenz auf den Snapshot, solange er läuft, und das gibt dem Garbage Collector etwas, um die Kette daran zu verankern. Dasselbe Leck existiert, langsamer und unregelmässiger, in einem Loop, der eine schlichte Coroutine direkt awaited, weil der Frame dieser Coroutine ebenfalls den aktuellen Kontext implizit hält. create_task ist der Fix für beide Formen.

Er kostet pro Iteration ein Task-Objekt. Auf einem Scheduler-Tick sind das ein paar hundert Bytes gegen einen Tick-Body, der aus Postgres liest. In einem heissen Inner Loop wäre das der falsche Trade-off. Die Regel, mit der wir herausgekommen sind: Umwickle den Body jedes langlebigen Loops, der Fremdcode anrufen kann, standardmässig in asyncio.create_task, und wickle ihn erst dann wieder aus, wenn die Task-Kosten gemessen sind und zählen.

Die generelle Lehre: Langlebige Coroutinen sind keine Request-Kontexte

Der tiefere Punkt ist, dass Pythons Async-Stack zwei sehr unterschiedliche Vorstellungen von Kontext-Lebensdauer kennt und sie von innen gleich aussehen. Die erste — ein Web-Request, ein geplanter Job, ein kurzlebiger Task — lebt in einem Task, und ihr Kontext stirbt, wenn der Task endet. Die zweite — ein Scheduler-Loop, ein Worker-Loop, ein Connection-Reader — lebt in dem Task, der sie erzeugt hat, oft dem Main-Task, und ihr Kontext lebt so lange wie der Prozess. Jede Bibliothek, die mit der ersten Lebensdauer im Kopf geschrieben wurde, verhält sich unter der zweiten still daneben.

Unser Scheduler war nicht der erste Ort, an dem uns das gebissen hat. Dieselbe Form — langlebiger Loop, Bibliothek, die ContextVar nutzt, langsames Leck, das für den eigenen Code unsichtbar ist — ist der Grund, warum wir auf einen eigenen Job-Table-Sweep umgestiegen sind, wie im Postgres-Job-Row-Backstop-Sweep-Artikel beschrieben: ein Loop, der seine Kontextgrenze pro Iteration selbst besitzt, statt sie vom Prozess zu erben. Und es ist derselbe Instinkt, der uns in der Worker-Split-mit-pg_notify-Aufzeichnung den Next.js-Worker aufteilen liess: Gib jeder Arbeits­einheit einen sauber begrenzten Scope, und nichts leckt über die Grenze.

Die Untersuchung selbst hat auch eine Lehre: tracemalloc-Snapshots, über ein langes Intervall gediffed, sind ein billigerer erster Debugger als objgraph, besonders für Lecks, die mit der Iterationsanzahl skalieren. Dreissig Sekunden tracemalloc.take_snapshot() → sleep → take_snapshot().compare_to(previous, "lineno") hätten im ersten Durchlauf auf TracebackType gezeigt, bevor wir einen halben Tag auf SQLAlchemy verwendet haben. Nächstes Mal greifen wir zuerst dorthin.

Wer einen Scheduler, einen Worker-Loop oder irgendeine langlebige async def-Funktion auf einem Web-Observability-Stack betreibt, sollte annehmen, dass mindestens eine seiner installierten Integrationen mit der falschen Annahme über Lebensdauer in eine ContextVar schreibt, und seinen Tick-Body in asyncio.create_task einwickeln — als billige Versicherung gegen die nächste. Dieselbe Disziplin trägt die Per-User-Analyse-Queue und den Serverless-Cold-Start-Warmup-Ping: Gib jeder Arbeitseinheit eine Kontextgrenze, die zu ihrer tatsächlichen Lebensdauer passt, nicht zur Lebensdauer des Prozesses, in dem sie zufällig lebt.

Wer ein langsames Leck auf einem Python-Backend verfolgt und die Top-Halter im tracemalloc-Diff TracebackType- und FrameType-Objekte sind, die er sich nicht erklären kann: Buchen Sie einen kostenlosen AI-Potenzial-Check — wir haben genau diese Form in der Produktion mehr als einmal debuggt.

Quellen: Python-Doku — contextvars · Python-Doku — asyncio.create_task · Sentry — Default-Python-Integrationen