💻 Entwicklung13. Juli 202622 Min. Lesezeit

Der Alarm sagte, die DB sei tot. Die DB war nie tot

Innerhalb eines Tages stapelten sich vier CRITICAL-Alarme. 504, Prisma P2028, ein 500er im Admin und 'DATABASE-Dienst ausgefallen'. Ich öffnete zuerst die RDS-Metriken: 21 Stunden lang lag die CPU bei maximal 19.7%, alles gesund. Langsam war nicht die DB, sondern ein Roundtrip, der fünfundzwanzigmal über den Atlantik ging. Und den Ausfall-Alarm hatte der Health Check selbst erzeugt.

Das Wichtigste

504, Prisma P2028, ein 500er im Admin, DATABASE ausgefallen. Von vier CRITICAL-Alarmen, die verschieden aussahen, kamen drei aus derselben Wurzel. Die Schreibzugriffe der eu-west-App überqueren den Atlantik zur us-east-Primary, und eine einzige Anfrage macht fünfundzwanzig Roundtrips. Die RDS langweilte sich derweil bei unter 20% CPU. Der Alarm 'DATABASE ausgefallen' war ein Fehlalarm, den der Health Check selbst erzeugt hatte: Weil DIRECT_DATABASE_URL nicht gesetzt war, schickte er sein SELECT 1 über genau den Proxy-Pfad, den die Schreibzugriffe der App gerade verstopften. Gefixt wurde nicht, indem wir das Timeout erhöhten, sondern indem wir die Roundtrips zusammenfalteten. Und ob der Canary erfolgreich war, entschieden wir nicht anhand der Latenz, sondern anhand der Queries pro Anfrage (22 -> 15.3).

Auf dieser Seite

Morgens öffnete ich Slack, und da lagen vier CRITICAL-Alarme.

504 AppHttpException: The request timed out.
  POST /customer/practice/attempts

PrismaClientKnownRequestError
  Transaction already closed

500 DriverAdapterError: canceling statement due to statement timeout
  GET /admin/dashboard/stats

DATABASE 서비스 다운
  "error": "Database health check (retry) timeout after 2000ms"

Die letzte Zeile ist die furchterregendste. Sie heißt: Die DB ist tot. Sieht man alle vier auf einem Bildschirm, zeichnet sich eine Geschichte ab. Die DB hatte zu kämpfen, deshalb stauten sich die Queries, deshalb liefen die Anfragen in ein Timeout, und am Ende scheiterte sogar der Health Check. Eine plausible Geschichte.

Also öffnete ich zuerst die DB-Metriken. Die Geschichte brach schon auf dem ersten Bildschirm zusammen.

Die DB langweilte sich 21 Stunden lang

Ich zog die RDS-Metriken für ein 21-Stunden-Fenster rund um den Vorfall im 5-Minuten-Raster. 252 Datenpunkte.

Metrik	Minimum	Maximum
CPU	4.6%	19.7%
Verbindungen	53	73
CPU-Credit-Guthaben	576	576
Leselatenz	0s	0.01s
Schreiblatenz	0.01s	0.08s

Die CPU hat 20% nie überschritten, und beim Credit-Guthaben sind Minimum und Maximum identisch. Es wurde also kein einziges verbraucht. Die Schreiblatenz lag bei maximal 80 Millisekunden. Auch den RDS Proxy sah ich mir an. Connection-Borrow-Latenz maximal 26 Millisekunden, maximal 36 Backend-Verbindungen. Nirgends eine Zahl, die eine Query von 8 oder 10 Sekunden erklären würde.

Die DB war nicht tot. Sie war nicht einmal beschäftigt.

Eine einzige Anfrage überquert den Atlantik fünfundzwanzigmal

Woher kam dann die 8-Sekunden-Query? Ein Blick auf die Architektur liefert die Antwort.

Unser Dienst läuft in zwei Regionen, us-east und eu-west. Die Primary-DB steht nur einmal in us-east; die Lesezugriffe der eu-west-App bedient eine lokale Replika, aber sämtliche Schreibzugriffe überqueren den Atlantik und gehen über den RDS Proxy zur us-east-Primary.

Das Problem war die Zahl der Schreibvorgänge. Ich verfolgte eine einzelne Anfrage zum Speichern eines Übungsversuchs (POST /customer/practice/attempts) im Code und zählte mit. 1x Asset-Upsert, 3x Lesen der Voraggregate, 4x Transaktion des Lernversuchs, 1x Neuabfrage durch den Runner, 2 bis 3x Fortschrittsaktualisierung, rund 6x Streak-Transaktion, 2x Statistik-Transaktion, 2 bis 3x Aktualisierung des Wiederholungsstatus. Über drei getrennte interaktive Transaktionsblöcke hinweg also etwa fünfundzwanzig.

Im Log stand genau diese Zahl.

06:03:17  request_done  POST /customer/practice/attempts
          status=201  duration_ms=11695  query_count=25

25 Queries, 11.7 Sekunden. Und diese Anfrage schlug nicht einmal fehl. Nach durchgestandenen 11.7 Sekunden kam sie mit 201 durch.

Hier muss ich etwas ehrlich offenlegen. Ich habe nicht gemessen, wie viele Millisekunden einer dieser Roundtrips kostet. Ein Codekommentar gibt die RTT zwischen den Regionen mit 220 Millisekunden an, ein anderer nennt 80 bis 100 Millisekunden pro Satz. Ohne geprüft zu haben, welcher der beiden stimmt, schrieb ich die Rechnung "25 x 220ms = 5.5 Sekunden" in den Issue-Text. Rückblickend ist das keine Messung, sondern ein Zitat. Die korrekte Aussage lautet: Die Zahl der Roundtrips habe ich gezählt (25), die Kosten pro Roundtrip habe ich nicht gemessen. Am Schluss ändert das trotzdem nichts. Wer den Atlantik fünfundzwanzigmal überquert, sammelt Kosten im Sekundenbereich an.

Im EU-Morgenpeak (06:00~06:10 UTC) ballten sich 57 Primary-Schreibvorgänge, die über 3 Sekunden brauchten. LearningAttempt.create 8,989ms, UserActiveDate.upsert 9,070ms, LearningAttempt.findUnique 10,561ms. Die Anfragen schoben sich gegenseitig, und die Roundtrip-Latenzen summierten sich.

Zwei der Alarme entstanden in dieser Lücke.

Alarm 1 und 2: Eine 5-Sekunden-Transaktion hielt 9.3 Sekunden nicht durch

Der Code für die Streak-Aktualisierung sah so aus.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... sechs Queries, die die Region ueberqueren ...
});

Kein Options-Objekt. Also greift Prismas Default-Timeout für interaktive Transaktionen von 5,000 Millisekunden. Im Normalfall ist das kein Problem. Solange man keine Region überquert.

Transaction API error: A query cannot be executed on an expired transaction.
The timeout for this transaction was 5000 ms,
however 9326 ms passed since the start of the transaction.

9,326 Millisekunden. Daraus wird P2028, und aus der Anfrage wird am Gateway ein 504.

Dieser Code war in unserer Codebasis der einzige ohne Schutz. Alle anderen Transaktionspfade laufen durch das Utility withTxRetry, das das Timeout auf 8 Sekunden anhebt und P2028 als retry-fähig behandelt. Nur die Streak-Aktualisierung stand außerhalb dieses Schirms und benutzte den Default von 5 Sekunden.

Alarm 4: Der Health Check lief durch genau den Engpass, den er überwachte

Der furchterregendste Alarm, "DATABASE-Dienst ausgefallen", war in Wahrheit der alberneste.

Der Health-Check-Code war gut geschrieben. Er wirft ein SELECT 1 mit 2 Sekunden Timeout, wartet bei einem Fehlschlag 500 Millisekunden, versucht es noch einmal, und schickt erst dann den CRITICAL-Alarm. Damit er sich nicht mit dem Prisma-Pool der App vermischt, bekam er sogar einen eigenen Connection-Pool (maximal 2). Der Entwurfsgedanke: Selbst wenn der App-Pool erschöpft ist, bleibt der Health Check am Leben.

Nur war der Pfad, über den diese Probe die DB erreicht, nicht isoliert.

// health.service.ts:139
// Wenn DIRECT_DATABASE_URL gesetzt ist, wird sie genutzt, sonst Fallback auf DATABASE_URL

DIRECT_DATABASE_URL war nicht gesetzt. Der Fallback griff, und DATABASE_URL zeigt auf genau den RDS Proxy, auf dem sich die Schreibzugriffe der App drängten. Das SELECT 1 der eu-west-Health-Probe musste also über den Atlantik, durch eben den Proxy, der gerade verstopfte, bis zur us-east-Primary und wieder zurück. In unter 2 Sekunden.

Der Code wusste davon. Er hinterlässt beim Fallback diese Warnung.

DIRECT_DATABASE_URL is not set; DB health checks will use DATABASE_URL
and may still share proxy bottlenecks.

Diese Zeile stand genau so im Log. Nur hatte sie niemand gelesen.

Der entscheidende Beleg war, dass beide Regionen zur selben Zeit gemeinsam ausfielen. 12:02:17, Timeout im Health Check des us-east-Tasks. 12:02:18, auch der eu-west-Task lief in ein Timeout. Wäre es ein regionales Problem gewesen, hätte nur eine Seite sterben dürfen. Dass beide zusammen starben, heißt: Ursache ist das, was sie teilen, also der Proxy-Pfad.

Was danach kommt, ist der vorgezeichnete Ablauf. Weil der Health Check zweimal fehlschlug, antwortet /public/health mit 503, der Orchestrator hält diesen Task für defekt und ersetzt ihn. Vier Minuten später war ein neuer Task da. Der neue Task lief direkt nach dem Booten in dasselbe Health-Check-Timeout. Ein Task-Austausch macht den Atlantik eben nicht schmaler.

"DATABASE-Dienst ausgefallen" war kein Symptom eines Ausfalls. Die Überwachung war selbst den verstopften Weg des Überwachten entlanggegangen und meldete anschließend, dass es ihr schlecht gehe.

Der 500er im Admin war eine eigene Sache

Hier kommt die Versuchung, alle vier Alarme zu einem zu bündeln. Auch ich wollte es zunächst so ordnen. Aber der 500er im Admin hatte eine andere Wurzel.

Wenn GET /admin/dashboard/stats die beliebten Wörter zieht, filtert es auf die letzten 7 Tage. Nur hat die Tabelle, auf die dieser Filter trifft (category_attempt), keine eigene Datumsspalte. Das Datum liegt allein auf der Seite der gejointen learning_attempt. Postgres hat also keine Möglichkeit, category_attempt vorab nach Datum zu beschneiden, und muss die gesamte Historie durchgehen. Egal wie gut man die Indizes legt, dieser Filter wird nicht selektiv.

slow_query path=/admin/dashboard/stats
           label=CategoryAttempt.groupBy dur=8009ms

Das statement_timeout liegt bei 8,000 Millisekunden. 8,009 Millisekunden. An 9 Millisekunden gescheitert. Ein Full Scan, der nichts mit Regionen zu tun hat und der zwangsläufig irgendwann platzt, sobald die Tabelle wächst.

Drei der vier Alarme hatten eine gemeinsame Wurzel, einer nicht. Dass vier Alarme auf einem Bildschirm auftauchen, heißt nicht, dass es eine einzige Ursache gibt.

Eine verworfene Hypothese

Es gab einen plausiblen Verdächtigen. Die Hypothese, dass der device-cleanup-Cron, der kurz vor dem 06:00-Burst läuft, Lock-Contention verursacht. Die Zeiten passten zusammen, das klang recht überzeugend.

Ich durchsuchte die Logs beider Regionen im Fenster 05:30~06:15. Kein einziger Log-Eintrag zum Cron. Ein Blick auf den Pfad des langsamen Device.updateMany zeigte kein Bulk-Update des Crons, sondern /v2/public/auth/refresh, also die ganz gewöhnliche Token-Erneuerung eines Nutzers. Die Hypothese wurde durch Messung verworfen. Dass sich Zeitfenster überlappen, ist Korrelation. Dass im Log nichts steht, ist eine Tatsache.

Wir haben die Roundtrips gefaltet

Es gibt zwei Wege. Man kann das Symptom aushalten: Timeout auf 8 Sekunden hoch, Pool vergrößern, Retry dranhängen. Man kann auch die Kosten selbst beseitigen: die Zahl der Roundtrips senken.

Wir haben beides getan. Der Streak-Transaktion withTxRetry überzuziehen ist ein Pflaster, aber ein nötiges. Die eigentliche Behandlung war jedoch, die Roundtrips zu falten.

Das Werkzeug dafür war längst gebaut. In einer Migration vom 27. Juni lag eine serverseitige Funktion namens create_practice_attempt_v1. Sie faltet Session-Lock, Abfrage, Insert, Aktualisierung der Session-Metadaten und das Lesen der Voraggregate in eine einzige SQL-Funktion und erledigt alles in einem Roundtrip. Sie ist sogar idempotent (ruft man sie zweimal mit derselben Client-Attempt-ID auf, gibt der zweite Aufruf die bestehende Zeile zurück und liefert inserted=false).

Nur stand das Feature-Flag, das diese Funktion einschaltet, PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, standardmäßig auf false und war in Produktion aus.

Statt Regionen abzuschaffen oder auf Active-Active umzustellen, bestand unsere Arbeit darin, einen längst gebauten Schalter umzulegen.

Canary: Woran entscheiden wir?

Das Flag schalteten wir nur in eu-west ein. us-east blieb als Kontrollgruppe aus. Task Definition von 786 auf 787 hoch, Rolling Deployment.

Woran wir das beurteilen, ist der Kern dieser Geschichte. Die Latenz ist eine Falle. Deployt man zu einer verkehrsarmen Zeit, wird der p95 besser, auch wenn man nichts repariert hat. Tatsächlich wurde die Latenz besser. Der p50 fiel von 2,784ms unter 2,000ms. Aber das ist ein schwacher Beleg.

Stattdessen sah ich mir die Zahl der Queries pro Anfrage an.

vorher  n=85   avg query_count = 22.0
nachher n=49   avg query_count = 15.3

Die Query-Zahl ist eine per-request-Metrik, die von der Last unabhängig ist. Ob viel oder wenig Traffic läuft: Wie viele Queries eine einzelne Anfrage abfeuert, entscheidet der Codepfad. Von 22 auf 15.3, rund 7 weniger. Und diese 7 stimmen exakt mit der Zahl der Queries überein, die wir in die eine Funktion gefaltet haben (Session-Lock + Abfrage + Insert + Session-Metadaten + Lesen der Voraggregate). Der Beleg dafür, dass sich der Codepfad wirklich geändert hat, ist diese Zahl. Nicht die Latenz.

Die Stichprobe nach dem Deployment umfasst 49 Fälle über 15 Minuten. In diesem Fenster gab es weder 5xx noch P2028, aber wir haben die Fehlerzahl eines gleich langen Vorher-Fensters am selben Tag nicht danebengelegt. Dieses Flag faltet nur das Speichern des Attempts. Die Streak-Transaktion überquert weiterhin die Region. Dass in diesem Fenster null P2028 auftraten, heißt, dass wir Glück hatten. Ein Beweis ist es nicht.

Das Deployment war erfolgreich, das Flag wäre fast verschwunden

Die Art, wie wir den Canary eingeschaltet haben, hatte ihren Preis. 787 ist eine Task Definition, die direkt in der Konsole registriert wurde. Läuft das nächste reguläre Deployment, überschreibt die CD-Pipeline sie mit einer Task Definition ohne das Flag. Fatal ist das nicht (beim Überschreiben fällt es auf das sichere OFF zurück). Nur verschwindet die Verbesserung still und leise.

Also mussten wir es nach Terraform überführen, und da kam die zweite Falle. Der Terraform-Workflow appliet bei einem Push auf develop nur Staging, Production nur bei einem Push auf main. In Staging gibt es aber überhaupt keine eu-west-Region. Ein PR mit einer Änderung an Produktion-eu-west, der nach develop gemerged wird, bewirkt also gar nichts. Wir mussten die Base auf main umstellen.

Es gab eine dritte Falle. Merged man direkt nach main, fällt develop zurück, und ohne Back-Merge revertiert der nächste Release diese Änderung. Wir mussten einen separaten Back-Merge-PR aufmachen.

"terraform apply war erfolgreich" und "es ist in Produktion angekommen" sind zwei verschiedene Sätze.

Was bleibt

Kommt ein Alarm "DB ausgefallen", öffnet man zuerst die DB-Metriken. Den Namen des Alarms hat der Code vergeben, der ihn abgeschickt hat, nicht die Ursache. Unser Health Check hatte sogar einen eigenen, vom App-Pool isolierten Pool, und war trotzdem zusammen mit der App blockiert, weil der Weg zur DB derselbe war. Isolation darf nicht nur die Ressourcen trennen, sie muss auch die Pfade trennen.

Hebt man das Timeout von 5 auf 8 Sekunden, verstummen die Alarme dieses Tages. Aber die Anfrage überquert den Atlantik weiterhin fünfundzwanzigmal. Wächst der Traffic nur ein wenig, reichen auch 8 Sekunden nicht mehr. Ob man das Symptom aushält oder die Kosten beseitigt, klärt man besser vorher. Wenn die Kosten "Anzahl x Distanz" sind, muss man die Anzahl senken.

Die Latenz schwankt mit der Last, per-request-Metriken schwanken nicht. Bevor man nach dem Deployment eines Performance-Fixes beruhigt auf einen besseren p95 schaut, sollte man prüfen, ob die Zahl der Dinge, die eine Anfrage tut, tatsächlich gesunken ist. Diese Zahl bleibt gleich, ob man nachts oder mittags deployt.

Ich habe die Zahl der Roundtrips gezählt, und die Latenz pro Roundtrip aus einem Codekommentar übernommen. Diese beiden Kommentare nannten verschiedene Werte. Zum Glück änderte das nichts am Schluss, aber das nächste Mal könnte es den Schluss ändern. Was wir nicht gemessen haben, schreiben wir als nicht gemessen hin.

Häufige Fragen

Ich bekomme den Health-Check-Alarm 'DATABASE-Dienst ausgefallen', aber die RDS-Metriken sind gesund. Wo muss ich hinsehen?

Prüfe, worüber der Health Check die DB überhaupt erreicht. Bei uns lief das SELECT 1 der Health-Probe über genau den RDS-Proxy-Pfad, auf dem sich der Schreib-Traffic der App staute. Wir hatten der Probe zwar einen eigenen Connection-Pool spendiert, um sie von einer Erschöpfung des App-Pools zu isolieren, aber das nützte nichts, weil der Pfad derselbe war. Ein Health Check muss die DB über einen Pfad erreichen, der so unabhängig wie möglich vom überwachten System ist. Sonst ist der Alarm kein Symptom eines Ausfalls, sondern das Echo einer Überlast.

Unsere regionsübergreifenden Schreibzugriffe sind langsam. Reicht es nicht, das Timeout zu erhöhen?

Mit einem höheren Timeout stirbt zwar nichts mehr, langsam bleibt es trotzdem. Wenn sich die Kosten aus 'Anzahl der Roundtrips x Latenz zwischen den Regionen' zusammensetzen, muss man die Anzahl der Roundtrips senken. Wir haben die fünfundzwanzig Roundtrips einer Anfrage in eine einzige serverseitige Funktion gefaltet und daraus einen Roundtrip gemacht. Das Timeout zu erhöhen heißt, das Symptom auszuhalten. Die Roundtrips zu falten heißt, die Kosten zu beseitigen.

Wir haben eine Performance-Verbesserung deployt. Woran entscheiden wir, ob sie wirklich etwas gebracht hat?

Wer nur auf die Latenz schaut, wird von der Last hin und her geschüttelt. Deployt man zu einer verkehrsarmen Zeit, sieht der p95 gut aus, auch wenn man nichts repariert hat. Sieh dir zusätzlich eine per-request-Metrik an, die von der Last unabhängig ist, etwa die Zahl der Queries pro Anfrage. Für uns war der entscheidende Beleg, dass die durchschnittliche Query-Zahl pro Anfrage von 22 auf 15.3 fiel. Denn die rund 7 weggefallenen Queries entsprachen exakt der Liste der Queries, die wir in die eine Funktion gefaltet hatten.