È arrivata la notifica che il DB era morto. Il DB non è mai morto

Ho aperto Slack la mattina e c'erano quattro alert CRITICAL in coda.

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"

L'ultima riga è la più spaventosa. Vuol dire che il DB è morto. Guardando i quattro alert su una sola schermata, si disegna una storia. Il DB era in difficoltà, quindi le query si sono accumulate, quindi le richieste sono andate in timeout, e alla fine è fallito anche l'health check. Una storia plausibile.

Perciò ho aperto per prime le metriche del DB. Quella storia è crollata alla prima schermata.

Il DB è rimasto tranquillo per 21 ore filate

Ho estratto le metriche RDS a intervalli di 5 minuti su una finestra di 21 ore che comprendeva l'orario dell'incidente. 252 data point.

Metrica	Minimo	Massimo
CPU	4.6%	19.7%
Connessioni	53	73
Saldo crediti CPU	576	576
Latenza di lettura	0s	0.01s
Latenza di scrittura	0.01s	0.08s

La CPU non ha mai superato il 20%, e il saldo dei crediti ha lo stesso valore minimo e massimo. Vuol dire che non ne è stato consumato nemmeno uno. La latenza di scrittura arriva al massimo a 80 millisecondi. Ho controllato anche RDS Proxy. Latenza massima di prestito delle connessioni 26 millisecondi, connessioni backend al massimo 36. Da nessuna parte c'è un numero che spieghi query da 8 o 10 secondi.

Il DB non era morto. Non era nemmeno impegnato.

Una singola richiesta attraversa l'Atlantico venticinque volte

E allora da dove vengono le query da 8 secondi? La risposta la dà la struttura.

Il nostro servizio gira su due regioni: us-east ed eu-west. Il DB primary sta solo in us-east; le letture dell'app eu-west le serve una replica locale, ma le scritture attraversano tutte l'Atlantico e vanno al primary us-east passando per RDS Proxy.

Il problema era il numero di scritture. Ho seguito nel codice una singola richiesta di salvataggio di un esercizio (POST /customer/practice/attempts) e le ho contate. 1 upsert di asset, 3 letture di aggregati precalcolati, 4 query nella transazione del tentativo di apprendimento, 1 rilettura del runner, 2-3 aggiornamenti di progresso, circa 6 query nella transazione della streak, 2 nella transazione delle statistiche, 2-3 aggiornamenti dello stato di ripasso. Circa venticinque, distribuite su tre blocchi di transazioni interattive indipendenti.

Nei log quel numero era stampato tale e quale.

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

25 query, 11.7 secondi. E questa richiesta non è nemmeno fallita. Dopo aver resistito 11.7 secondi, è riuscita con un 201.

Qui devo dichiarare una cosa con onestà. Quanti millisecondi costi ognuno di questi andirivieni, io non l'ho misurato. Un commento nel codice riportava un RTT tra regioni di 220 millisecondi, un altro commento parlava di 80-100 millisecondi per frase. Senza verificare quale dei due fosse quello giusto, nel corpo della issue ho scritto il calcolo "25 x 220ms = 5.5 secondi". A rileggerlo ora, quella non è una misura: è una citazione. L'affermazione esatta è questa. Il numero di andate e ritorni l'ho contato (25), il costo per andata e ritorno non l'ho misurato. La conclusione, comunque, non vacilla. Se attraversi l'Atlantico venticinque volte, il costo si accumula nell'ordine dei secondi.

Durante il picco mattutino EU (06:00-06:10 UTC) si sono accalcate 57 scritture sul primary oltre i 3 secondi. LearningAttempt.create 8,989ms, UserActiveDate.upsert 9,070ms, LearningAttempt.findUnique 10,561ms. Le richieste si spingevano a vicenda e le latenze degli andirivieni si sommavano.

Due degli alert sono usciti da quella crepa.

Alert 1 e 2: una transazione da 5 secondi non ha retto 9.3 secondi

Il codice che aggiorna la streak era fatto così.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... sei query che attraversano la regione ...
});

Non c'è l'oggetto delle opzioni. Quindi si applica il timeout di default delle transazioni interattive di Prisma: 5,000 millisecondi. Di solito non è un problema. Se non attraversi le regioni.

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 millisecondi. E questo diventa P2028, e la richiesta diventa un 504 sul gateway.

Questo codice era l'unico scoperto in tutta la nostra codebase. Gli altri percorsi transazionali passano dall'utility withTxRetry, che alza il timeout a 8 secondi e considera P2028 come caso da ritentare. Solo l'aggiornamento della streak era rimasto fuori da quell'ombrello, con il default di 5 secondi.

Alert 4: l'health check ha attraversato il collo di bottiglia che stava sorvegliando

Il più spaventoso, "servizio DATABASE down", era in realtà il più assurdo.

Il codice dell'health check era scritto bene. Lancia un SELECT 1 con timeout di 2 secondi, e se fallisce aspetta 500 millisecondi e riprova una volta; se fallisce anche allora, spara l'alert CRITICAL. Per non mescolarsi con il pool di Prisma dell'app, aveva perfino un connection pool dedicato (massimo 2 connessioni). Il design serve a tenere in vita l'health check anche se il pool dell'app si esaurisce.

Solo che il percorso con cui questa probe raggiunge il DB non era isolato.

// health.service.ts:139
// Se DIRECT_DATABASE_URL esiste la si usa, altrimenti si ripiega su DATABASE_URL

DIRECT_DATABASE_URL non era impostata. È scattato il fallback, e DATABASE_URL punta esattamente a quell'RDS Proxy su cui si accalcavano le scritture dell'app. Cioè: il SELECT 1 lanciato dalla probe di health di eu-west doveva attraversare l'Atlantico, passare per il proxy che in quel momento era intasato, arrivare fino al primary us-east e tornare indietro. In meno di 2 secondi.

Il codice questa cosa la sapeva. Quando scatta il fallback, è previsto che lasci questo avviso.

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

Nei log questa riga era stampata tale e quale. Solo che nessuno l'aveva letta.

La prova decisiva è che le due regioni sono fallite insieme, allo stesso istante. 12:02:17, timeout dell'health check sul task us-east. 12:02:18, timeout anche sul task eu-west. Se fosse stato un problema locale, sarebbe dovuto morire un lato solo. Che siano morti insieme significa che la causa è ciò che condividono, cioè il percorso attraverso il proxy.

Il resto è la sequenza annunciata. Poiché l'health check è fallito entrambe le volte, /public/health restituisce 503, l'orchestratore considera il task problematico e lo sostituisce. Quattro minuti dopo è partito il nuovo task. Il nuovo task, appena avviato, si è ripreso lo stesso identico timeout dell'health check. Cambiare il task non restringe l'Atlantico.

"Servizio DATABASE down" non era il sintomo di un guasto. Era lo strumento di sorveglianza che, dopo aver percorso la strada congestionata di ciò che sorvegliava, segnalava di essere lui in difficoltà.

Il 500 dell'admin era un'altra faccenda

A questo punto arriva la tentazione di legare i quattro alert in un unico nodo. All'inizio volevo sistemarli così anch'io. Ma il 500 dell'admin aveva una radice diversa.

Quando GET /admin/dashboard/stats estrae le parole più frequenti, applica un filtro sugli ultimi 7 giorni. Solo che la tabella su cui cade quel filtro (category_attempt) non ha una colonna data propria. La data sta soltanto dal lato di learning_attempt, che viene messa in join. Quindi Postgres non ha modo di potare in anticipo category_attempt per data, e deve scorrere tutto lo storico. Per quanti indici tu metta, questo filtro non lo rendi selettivo.

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

Lo statement_timeout è 8,000 millisecondi. 8,009 millisecondi. È morto per 9 millisecondi di differenza. Una full scan che non c'entra nulla con le regioni e che, con la tabella che cresce, prima o poi sarebbe esplosa comunque.

Tre alert su quattro avevano la stessa radice, uno no. Che quattro alert compaiano sulla stessa schermata non vuol dire che la causa sia una sola.

Un'ipotesi respinta

C'era un sospettato piuttosto plausibile. L'ipotesi che il cron di device-cleanup, che gira poco prima del burst delle 06:00, provocasse contesa sui lock. Gli orari combaciavano, quindi era abbastanza convincente.

Ho passato al setaccio i log delle due regioni nella finestra 05:30-06:15. Non c'era un solo log relativo al cron. Controllando il percorso della lenta Device.updateMany, non era il bulk update del cron ma /v2/public/auth/refresh, cioè le normali richieste di refresh del token degli utenti. L'ipotesi è stata respinta dalla misura. Che gli orari coincidano è correlazione; che nei log non ci sia nulla è un fatto.

Abbiamo ripiegato gli andirivieni

Le strade della cura sono due. C'è quella di sopportare il sintomo: alzi il timeout a 8 secondi, ingrandisci il pool, aggiungi i retry. E c'è quella di eliminare il costo stesso: riduci il numero di andate e ritorni.

Le abbiamo fatte entrambe. Mettere withTxRetry sulla transazione della streak è un cerotto, ma era un cerotto necessario. La cura vera, però, era ripiegare gli andirivieni.

Lo strumento era già stato costruito. In una migration datata 27 giugno c'era una funzione server-side chiamata create_practice_attempt_v1. È una funzione che ripiega in un'unica funzione SQL il lock della sessione, la lettura, l'inserimento, l'aggiornamento dei metadati di sessione e la lettura degli aggregati precalcolati, chiudendo tutto in una sola andata e ritorno. È perfino idempotente (se la chiami due volte con lo stesso client attempt id, la seconda ti restituisce la riga esistente e ritorna inserted=false).

Solo che il feature flag che accende questa funzione, PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, aveva default false ed era spento in produzione.

Invece di eliminare una regione o passare all'active-active, quello che abbiamo fatto è stato accendere un interruttore già costruito.

Canary: in base a che cosa decidere

Ho acceso il flag solo su eu-west. Su us-east l'ho lasciato spento, come gruppo di controllo. Ho portato la task definition da 786 a 787 e ho fatto un rolling deploy.

Il cuore di questa storia è quale metrica prendere come giudice. La latenza è una trappola. Se rilasci in una fascia oraria a traffico scarico, il p95 migliora anche senza aver corretto nulla. E in effetti la latenza è migliorata: il p50 è sceso da 2,784ms a sotto i 2,000ms. Ma è una prova debole.

Ho guardato invece il numero di query per richiesta.

prima   n=85   avg query_count = 22.0
dopo    n=49   avg query_count = 15.3

Il numero di query è una metrica per richiesta indipendente dal carico. Che il traffico sia tanto o poco, quante query lancia una singola richiesta lo decide il percorso di codice. Da 22 a 15.3: circa 7 in meno. E quelle 7 coincidono esattamente con il numero di query dell'elenco che avevamo ripiegato in una sola funzione (lock della sessione + lettura + inserimento + metadati di sessione + lettura degli aggregati precalcolati). La prova che il percorso di codice è davvero cambiato è questo numero. Non la latenza.

Il campione dopo il rilascio è di 49 richieste in 15 minuti. In quella finestra i 5xx e i P2028 sono stati entrambi 0, ma non ho misurato in parallelo il numero di errori "prima del rilascio" nello stesso giorno e su una finestra della stessa lunghezza. Questo flag ripiega solo il salvataggio del tentativo. La transazione della streak continua ad attraversare le regioni. Che in quella finestra i P2028 fossero 0 vuol dire che siamo stati fortunati, non è una dimostrazione.

Il deploy è riuscito, ma il flag stava per sparire

Il modo in cui abbiamo acceso la canary aveva un prezzo. La 787 è una task definition registrata a mano dalla console. Al prossimo rilascio ufficiale, la pipeline di CD la sovrascrive con una task definition priva del flag. Non è fatale (se la sovrascrive, si torna all'OFF che è sicuro). Solo che il miglioramento sparisce in silenzio.

Bisognava quindi promuoverlo su terraform, e qui è saltata fuori la seconda trappola. Il workflow terraform, sulla push su develop, fa apply solo su staging; la produzione la applica solo sulla push su main. Ma su staging la regione eu-west non esiste proprio. Cioè: se mergi su develop una PR che contiene una modifica alla eu-west di produzione, non succede assolutamente nulla. Bisognava cambiare la base in main.

C'era una terza trappola. Se mergi direttamente su main, develop resta indietro, e se non fai la merge di ritorno la prossima release ti fa il revert della modifica. Bisognava aprire una PR di back-merge a parte.

"Il terraform apply è andato a buon fine" e "è arrivato in produzione" sono due frasi diverse.

Quel che resta

Quando arriva un alert "DB down", la prima cosa da aprire sono le metriche del DB. Il nome dell'alert glielo ha dato il codice che l'ha sparato, non la causa. Il nostro health check si era costruito perfino un pool dedicato, isolato da quello dell'app, e nonostante questo si è intasato insieme all'app perché la strada verso il DB era la stessa. Isolare non vuol dire solo dividere le risorse: bisogna dividere anche i percorsi.

Se alzi il timeout da 5 a 8 secondi, gli alert di quel giorno si fermano. Ma la richiesta continua ad attraversare l'Atlantico venticinque volte. Basta che il traffico cresca un po' e anche 8 secondi diventano pochi. Meglio decidere in anticipo se si vuole sopportare il sintomo o eliminare il costo. Se il costo è fatto di "numero x distanza", quello da ridurre è il numero.

La latenza oscilla con il carico, le metriche per richiesta no. Prima di rilassarti perché hai rilasciato una correzione di performance e il p95 è migliorato, guarda se il numero di cose che fa una singola richiesta è davvero diminuito. Quel numero è lo stesso sia che tu rilasci all'alba sia che tu rilasci a mezzogiorno.

Il numero di andate e ritorni l'ho contato; la latenza per andata e ritorno l'ho presa da un commento nel codice. E quei due commenti dicevano valori diversi tra loro. Per fortuna la conclusione non è cambiata, ma la prossima volta potrebbe cambiare. I numeri che non abbiamo misurato, scriviamo che non li abbiamo misurati.