Die Hälfte unserer Hintergrundjobs hatte ein Zeitlimit, das niemand gewählt hat

Ein Funktionsaufruf kehrt zurück oder wirft eine Exception. Damit kannst du rechnen. Ein Modellaufruf tut beides nicht zuverlässig: er kehrt irgendwann zurück, in einer Zeit aus einer Verteilung mit einem langen und wirklich hässlichen Rand. Steckst du einen davon in eine Schleife über den Upload-Batch eines Nutzers, hast du keine Funktion mehr geschrieben. Du hast eine Wette geschrieben.

Diese Wette haben wir eine Weile im Maßstab laufen lassen, ohne es zu merken. Norman macht Buchhaltung und Steuererklärungen für deutsche Unternehmen, und das heißt in der Praxis: viel unglamouröse Hintergrundarbeit. Belege lesen, Kategorien zuordnen, Zahlungen abgleichen, Querysets durchlaufen, Meldungen vorbereiten. Knapp eine Million Transaktionen und rund 40.000 neue Dokumente pro Monat laufen durch diese Maschinerie. Das meiste davon passiert in einer Queue, und überraschend viel davon ruft irgendwo in der Mitte ein Sprachmodell auf.

So sehen diese Modellaufrufe in der Produktion tatsächlich aus, gemessen über den letzten Monat an Agent-Schritten: deutlich über hunderttausend Aufrufe, der Median bei etwa fünfeinhalb Sekunden, p99 bei rund 35 Sekunden, und der langsamste einzelne Aufruf, den wir dokumentiert haben, lief knapp elf Minuten. Die deterministischen Tool-Aufrufe in denselben Runs haben einen Median im Bereich von Dutzenden Millisekunden. Zwei Größenordnungen Unterschied, im selben Code-Pfad, und der langsame ist genau der, den du nicht begrenzen kannst.

Jetzt die Pointe: Jeder Hintergrund-Task, der es nicht ausdrücklich anders deklariert hat, lief mit einem Soft-Budget von 120 Sekunden.

Niemand hat es gesetzt, deshalb hat es niemand hinterfragt

Das Budget kam nicht aus einer Design-Diskussion. Es kam aus einem Container-Image. Unser Worker-Entrypoint startete fünf Celery-Master, einen pro Queue, und jede Kommandozeile endete auf etwas wie --soft-time-limit ${SOFT_TIME_LIMIT:-120}. Keine Umgebung hat SOFT_TIME_LIMIT jemals gesetzt. Also gewann der Fallback, überall, dauerhaft.

Interessant ist vor allem, warum das kein Code Review aufgefangen hat. Etwa die Hälfte unserer gut hundert Tasks deklariert ihre Limits im Decorator, und die sahen in Ordnung aus. Die andere Hälfte sah auch in Ordnung aus, weil ein Task ohne Limit sich liest wie "kein Limit". Das bedeutet es aber nicht. Celery löst das effektive Budget über die Pool-Defaults des Workers auf, und ein Kommandozeilen-Flag schlägt die Anwendungskonfiguration bedingungslos. task_soft_time_limit in unserem Settings-Modul war also nicht die Quelle der Wahrheit, und ein Blick ins Settings-Modul erzählte dir eine bequeme Lüge.

Zu den Tasks, die diese 120 Sekunden geerbt haben, gehörten komplette Queryset-Durchläufe und Massen-OCR-Schleifen. Einer davon nimmt bis zu 95 Dateien in einem einzigen Job an, lässt über jede OCR plus einen Modelldurchlauf laufen, und hatte insgesamt weniger Zeit als ein einzelner Modellaufruf im Worst Case.

Der Fix selbst sind drei Zeilen und ein gelöschtes Flag: die Flags von den transaktionalen Queues entfernen, die Zahlen in die Konfiguration holen, wo sie sichtbar und überschreibbar sind, und den Decorator eines Tasks weiterhin gewinnen lassen. Der Default liegt jetzt bei 600 Sekunden soft und 900 hart. Die Agent-Queues behalten explizite Flags, weil ihre Budgets nicht dieselben sein sollen wie alles andere: Batch-Agentarbeit bekommt ein großzügiges Soft-Limit, während die interaktive Queue, auf die ein Mensch wartet, ein knappes bekommt. Ein Budget ist eine Produktentscheidung. Es gehört dorthin, wo ein Reviewer es sieht, mit einem Kommentar daneben, der die Wahl erklärt.

Das Timeout-Signal ist eine Exception, und deine Schleife hat sie längst gefangen

Das ist der Teil, den ich auf ein Poster drucken würde.

Celerys Soft-Time-Limit funktioniert, indem es eine Exception in deinem Task auslöst. In unserem Fall erbt diese Exception direkt von Exception. Und jetzt denk an die Form, zu der praktisch jeder Batch-Job in jeder Codebase konvergiert:

for item in batch:
    try:
        process(item)
    except Exception:
        logging.exception("item failed")
        job.record_failure(item)

job.status = "completed"
job.save()

Diese Schleife ist richtig, was Fehler einzelner Items betrifft, und katastrophal falsch, was Zeitlimits betrifft. Wenn das Soft-Limit feuert, wird das Abbruchsignal dem Item angelastet, das gerade zufällig in Arbeit war, als dessen Problem markiert und verschluckt. Die Schleife läuft weiter zum nächsten Item, und zum nächsten, bis das harte Limit kommt und den Worker-Prozess mit SIGKILL beendet. Damit läuft der Code nach der Schleife nie. Die Job-Zeile verlässt importing nie. Keine Zusammenfassungs-Mail geht raus. Der Nutzer sieht einen Spinner, der bis zum Wärmetod des Universums dreht.

Der Beweis lag die ganze Zeit in der Datenbank. Von rund 8.300 CSV-Import-Jobs hingen knapp hundert in importing fest, die meisten aus dem vorangegangenen Monat, und im Durchschnitt hatten sie schon einige hundert Zeilen geschrieben, bevor sie verstummten. Dasselbe Muster bei Massen-Uploads: eine Handvoll in processing, keiner davon jung genug, um noch zu laufen. Dasselbe Muster in den Agent-Tabellen, wo ein paar hundert Runs aus dem letzten Monat ohne Endstatus in running stehen. Drei verschiedene Subsysteme, ein Bug, unabhängig voneinander von verschiedenen Leuten geschrieben, weil die Form des Fehlers die Form von normalem defensivem Code ist.

Der Fix besteht darin, das Zeitlimit nicht länger als Fehler des aktuellen Items zu behandeln, denn das ist es nicht. Es ist die Runtime, die den Task bittet zu gehen:

for i, item in enumerate(batch):
    try:
        process(item)
    except SoftTimeLimitExceeded:
        # Nicht die Schuld dieses Items. Festhalten, wie weit wir kamen,
        # dann Platz machen: als Naechstes kommt das harte Limit, und das
        # fuehrt keinen Cleanup-Code mehr aus.
        job.set_failed(f"timed out after {i} of {len(batch)} items")
        raise
    except Exception:
        job.record_failure(item)

Zwei Eigenschaften sind hier wichtig. Erstens wird der Abbruch erneut geworfen, damit der Worker den Task in dem Fenster zwischen Soft- und Hard-Limit herunterfahren kann, und genau dafür existiert dieses Fenster. Zweitens wird der Job vor dem erneuten Werfen finalisiert, damit die Zeile in einem Endzustand landet, den die UI rendern und ein Mensch bearbeiten kann. "Nach 340 von 1.772 Zeilen abgebrochen, bitte die Datei aufteilen und erneut versuchen" ist ein schlechtes Ergebnis. importing für immer ist überhaupt kein Ergebnis.

Auch in den Hilfsfunktionen mussten wir aufpassen. Wenn du die Arbeit pro Item in eine eigene Funktion mit eigenem Catch-all auslagerst, wird das Signal eine Ebene tiefer verschluckt und erreicht die Schleife nie. Jeder Helper, der Modellarbeit umschließt, wirft den Abbruch jetzt ausdrücklich weiter, bevor sein allgemeiner Handler greift.

Eine schlechte Zeile ist kein Grund, das Queryset aufzugeben

Das Spiegelbild dieses Bugs ist der Durchlauf ohne jede Fehlerbehandlung.

Mehrere unserer geplanten Jobs waren ein nacktes for invoice in qs.iterator(): mit der eigentlichen Arbeit inline. Die erste Zeile, die eine Exception warf, beendete den Task und ließ den kompletten Rest des Querysets stillschweigend liegen, bis zum nächsten geplanten Lauf, der dann auf dieselbe vergiftete Zeile traf und an derselben Stelle wieder aufhörte. In den Logs stand nichts von "dieser Durchlauf ist nicht fertig geworden", denn aus Celerys Sicht hat der Task geworfen, und damit war die Sache erledigt.

Der Produktionsbefund war bei einem dieser Jobs deutlich: Ein paar hundert Rechnungen passten auf das Queryset des Überfälligkeits-Durchlaufs, die meisten davon seit einem Monat oder länger fällig, während tatsächlich nur ein bis zwei Dutzend Zeilen den Status "überfällig" trugen. Der Durchlauf war lange früh gestorben.

Die Sweeps teilen sich deshalb jetzt einen kleinen Helper mit bewusst nüchternem Docstring: wende dieses Callable auf jede Zeile an, zähle, was ging und was nicht, isoliere Fehler pro Zeile und log eine Zusammenfassung auf Warning-Level, wenn etwas fehlschlug. Und, entscheidend, wirf das Zeitlimit weiter, denn das ist ein Grund aufzuhören. Die Unterscheidung, um die sich dieser ganze Artikel dreht, in einer Funktion: eine schlechte Zeile heißt weitermachen, ein Zeitlimit heißt rausgehen.

Die Zusammenfassungs-Logzeile ist wichtiger, als sie aussieht. processed=571 failed=20 auf Warning-Level ist eine Metrik, auf die du alarmieren kannst. Ein lautlos abgeschnittener Durchlauf ist keine.

Gib das Budget dem Modell, nicht der Referenztabelle

Als die Tasks ehrliche Zeitlimits hatten, war die nächste Frage, wofür sie sie ausgeben. Ein Teil der Antwort war peinlich.

Unsere eingebaute Kategorientabelle ist statische Referenzdaten: ein paar Dutzend Blattzeilen, geändert nur durch eine Migration, ohne Dimension pro Unternehmen, und sie passt in etwa 128 kB. Der OCR-Extraktor und die Prompt-Builder haben sie für jedes einzelne Dokument und jede einzelne Transaktion komplett neu gelesen. In einem Batch ist das ein vollständiger sequenzieller Scan pro Zeile. Kumuliert zeigten die Zähler eine halbe Milliarde sequenzielle Scans über die Lebenszeit und zweistellige Milliardenbeträge gelesener Tupel auf dieser einen winzigen Tabelle.

Nichts davon ist langsam, wie eine langsame Query langsam ist. Jeder Scan liegt unter einer Millisekunde. Es ist langsam, wie tausend Dinge unter einer Millisekunde in einer Schleife pro Zeile langsam sind: im Profil unsichtbar, in der Batch-Laufzeit sehr sichtbar. Ein Cache über die Prozesslebenszeit mit lru_cache und einem post_save-Hook zur Invalidierung, nach demselben Muster, das wir schon für Währungs-Lookups nutzten, hat das entfernt. Langweilig, mechanisch, und es gibt die zurückgewonnenen Sekunden dem Teil der Pipeline, der sie braucht.

Eine Anmerkung dazu, wie wir gemessen haben, denn zuerst haben wir es falsch gemacht

Eine frühere Version des Docstrings zu diesem Cache behauptete selbstbewusst eine Aufteilung zwischen Request-Pfad und Batch-Last, gemessen durch zweimaliges Abfragen der Postgres-Statistiken und Bildung der Differenz. Die Zahl war falsch, und der Grund ist es wert, weitergegeben zu werden: Postgres 15 setzt stats_fetch_consistency per Default auf cache, was den Statistik-Snapshot für die Dauer einer Transaktion einfriert. Beide Lesevorgänge lagen in einer Transaktion, der zweite gab also die Zahlen des ersten zurück, und die Differenz war Rauschen im Kostüm eines Befunds.

Korrekt nachgemessen, mit Autocommit, zeigte dieselbe Tabelle in einem Fenster rund 990 Scans pro Sekunde und fünf Minuten später unter 40. Die Last ist stoßweise, und die behauptete Aufteilung war nie belegt. Wir haben die Aussage im Docstring zurückgezogen, statt sie still zu löschen, und nur mit dieser Variante bin ich einverstanden.

Wenn du eine operative Angewohnheit aus diesem Text mitnimmst, dann diese: sample pg_stat_* mit Autocommit, sonst sind deine Deltas Fiktion.

Wofür ein Zeitlimit eigentlich da ist

Der Reflex, wenn ein Job in ein Timeout läuft, ist, das Limit hochzusetzen. Wir haben das Limit hochgesetzt, und es war das Uninteressanteste, was wir getan haben.

Ein Zeitlimit ist kein Hindernis, um das man herumfährt. Es ist der Mechanismus, durch den unbegrenzte Arbeit begrenzt wird, und sobald du akzeptierst, dass ein Modellaufruf unbegrenzte Arbeit ist, braucht jeder Batch, der einen enthält, drei Dinge: ein Budget, das jemand bewusst gewählt und mit Begründung aufgeschrieben hat; ein dokumentiertes Verhalten für den Fall, dass dieses Budget aufgeht, das damit endet, dass der Job in einem Endzustand steht, den ein Mensch sieht; und Isolation pro Item, damit eine schlechte Zeile nicht den Batch mitnimmt.

Nichts davon ist KI-Engineering in dem Sinn, in dem der Begriff meist benutzt wird. In diesem Artikel steht kein einziger Prompt. Aber es ist das meiste von dem, was einen Agenten, der in der Demo funktioniert, von einem trennt, der auf 40.000 Dokumenten pro Monat funktioniert, und dorthin geht ein unverhältnismäßig großer Teil unserer Zuverlässigkeitsarbeit. Das Modell ist der Teil, der Aufmerksamkeit bekommt. Die Queue ist der Teil, der entscheidet, ob dem Ergebnis jemand traut.