Une alerte disait que la base était morte. La base n'est jamais morte

Au matin, j'ouvre Slack : quatre alertes CRITICAL empilées.

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"

C'est la dernière ligne qui fait le plus peur. Elle dit que la base est morte. Vues sur un même écran, les quatre dessinent une histoire. La base a souffert, donc les requêtes se sont accumulées, donc les requêtes HTTP ont expiré, et finalement même le health check a échoué. Une histoire plausible.

Alors j'ai commencé par ouvrir les métriques de la base. L'histoire s'est effondrée dès le premier écran.

La base est restée tranquille pendant 21 heures

J'ai extrait les métriques RDS par pas de 5 minutes sur une fenêtre de 21 heures incluant l'incident. 252 points de données.

Métrique	Min	Max
CPU	4,6 %	19,7 %
Connexions	53	73
Solde de crédits CPU	576	576
Latence de lecture	0s	0,01s
Latence d'écriture	0,01s	0,08s

Le CPU n'a jamais dépassé 20 %, et le solde de crédits a le même minimum et le même maximum. Autrement dit, rien n'a été consommé. La latence d'écriture culmine à 80 millisecondes. J'ai aussi vérifié RDS Proxy : latence d'emprunt de connexion maximale de 26 millisecondes, 36 connexions backend au maximum. Nulle part un chiffre capable d'expliquer des requêtes de 8 ou 10 secondes.

La base n'était pas morte. Elle n'était même pas occupée.

Une seule requête traverse l'Atlantique vingt-cinq fois

D'où sortent alors ces requêtes de 8 secondes ? La structure donne la réponse.

Notre service tourne dans deux régions, us-east et eu-west. Il n'y a qu'une seule base primary, en us-east : les lectures de l'app eu-west sont servies par un réplica local, mais toutes les écritures traversent l'Atlantique et passent par RDS Proxy jusqu'au primary us-east.

Le problème, c'était le nombre d'écritures. J'ai suivi une requête d'enregistrement d'exercice (POST /customer/practice/attempts) dans le code, en comptant. 1 upsert d'asset, 3 lectures d'agrégats précalculés, 4 dans la transaction de tentative d'apprentissage, 1 relecture par le runner, 2 à 3 mises à jour de progression, environ 6 dans la transaction de série (streak), 2 dans la transaction de statistiques, 2 à 3 mises à jour de l'état de révision. Environ vingt-cinq, réparties sur trois blocs de transactions interactives indépendantes.

Ce chiffre était inscrit tel quel dans les logs.

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

25 requêtes SQL, 11,7 secondes. Et cette requête n'a même pas échoué. Après avoir tenu 11,7 secondes, elle a réussi avec un 201.

Il y a ici une chose à avouer honnêtement. Je n'ai pas mesuré le coût en millisecondes d'un seul de ces allers-retours. Un commentaire dans le code indiquait un RTT inter-régions de 220 millisecondes, un autre annonçait 80 à 100 millisecondes par phrase. Sans avoir vérifié lequel des deux était juste, j'ai écrit le calcul « 25 x 220 ms = 5,5 s » dans le corps de l'issue. Avec le recul, ce n'est pas une mesure, c'est une citation. L'énoncé exact est celui-ci : j'ai compté le nombre d'allers-retours (25), et je n'ai pas mesuré le coût par aller-retour. La conclusion ne vacille pas pour autant. Vingt-cinq allers-retours au-dessus de l'Atlantique, et le coût se compte en secondes.

Au pic matinal européen (06:00-06:10 UTC), 57 écritures sur le primary ont dépassé les 3 secondes. LearningAttempt.create 8 989 ms, UserActiveDate.upsert 9 070 ms, LearningAttempt.findUnique 10 561 ms. Les requêtes se poussaient les unes les autres et la latence des allers-retours s'empilait.

Deux des alertes sont sorties de cet interstice.

Alertes 1 et 2 : une transaction à 5 secondes n'a pas tenu 9,3 secondes

Le code de mise à jour de la série ressemblait à ceci.

// streak.service.ts:254
const changed = await this.prisma.primary.$transaction(async (tx) => {
  // ... six requetes qui traversent la region ...
});

Pas d'objet d'options. Donc le timeout par défaut des transactions interactives de Prisma s'applique : 5 000 millisecondes. En temps normal, aucun problème. À condition de ne pas traverser une frontière de région.

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 millisecondes. Cela devient un P2028, et la requête devient un 504 à la passerelle.

Ce code était le seul sans protection dans toute notre base de code. Les autres chemins transactionnels passent par l'utilitaire withTxRetry, qui monte le timeout à 8 secondes et traite P2028 comme un cas à réessayer. Seule la mise à jour de la série était restée hors de ce parapluie, avec la valeur par défaut de 5 secondes.

Alerte 4 : le health check est passé par le goulot qu'il surveillait

Le « service DATABASE down », le plus effrayant des quatre, était en réalité le plus absurde.

Le code du health check était bien écrit. Il envoie un SELECT 1 avec un timeout de 2 secondes, et en cas d'échec, il attend 500 millisecondes puis retente une fois ; si cela échoue encore, il déclenche une alerte CRITICAL. Il dispose même d'un pool de connexions dédié (2 au maximum) pour ne pas se mélanger au pool Prisma de l'app. L'idée : que le health check survive même si le pool applicatif est épuisé.

Sauf que le chemin par lequel cette sonde atteint la base, lui, n'était pas isolé.

// health.service.ts:139
// Si DIRECT_DATABASE_URL existe on l'utilise, sinon on retombe sur DATABASE_URL

DIRECT_DATABASE_URL n'était pas configurée. Le fallback s'est déclenché, et DATABASE_URL pointe précisément vers le RDS Proxy où s'entassent les écritures de l'app. Autrement dit, le SELECT 1 lancé par la sonde de santé d'eu-west devait traverser l'Atlantique, franchir ce proxy en train de se boucher, atteindre le primary us-east et revenir. En moins de 2 secondes.

Le code était au courant. Il était prévu pour laisser un avertissement quand le fallback se déclenche.

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

Cette ligne était bien là, dans les logs. Personne ne l'avait lue, voilà tout.

La preuve décisive : les deux régions ont échoué au même instant. 12:02:17, timeout du health check de la tâche us-east. 12:02:18, timeout de la tâche eu-west aussi. Si le problème avait été régional, un seul côté aurait dû tomber. Qu'ils tombent ensemble signifie que la cause est ce qu'ils partagent, c'est-à-dire le chemin proxy.

La suite était écrite d'avance. Le health check ayant échoué deux fois, /public/health renvoie un 503, l'orchestrateur considère la tâche comme défaillante et la remplace. Quatre minutes plus tard, une nouvelle tâche démarre. Et à peine démarrée, elle se prend exactement le même timeout de health check. Remplacer une tâche ne rétrécit pas l'Atlantique.

« Service DATABASE down » n'était pas le symptôme d'une panne. C'était l'appareil de surveillance qui, après avoir emprunté la route congestionnée de ce qu'il surveillait, rapportait sa propre souffrance.

Le 500 de l'admin était un cas à part

À ce stade, la tentation vient de nouer les quatre alertes en une seule. Moi aussi, au début, j'ai voulu les ranger comme ça. Mais le 500 de l'admin avait une autre racine.

Quand GET /admin/dashboard/stats extrait les mots populaires, il filtre sur les 7 derniers jours. Or la table sur laquelle porte ce filtre (category_attempt) n'a pas de colonne de date à elle. La date n'existe que du côté de learning_attempt, la table jointe. Postgres n'a donc aucun moyen de découper category_attempt par date en amont : il doit balayer tout l'historique. Aucun index, si bien posé soit-il, ne rendra ce filtre sélectif.

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

Le statement_timeout est à 8 000 millisecondes. 8 009 millisecondes. Mort pour 9 millisecondes. Un full scan sans aucun rapport avec les régions, et qui aurait fini par exploser tôt ou tard, à mesure que la table grossissait.

Sur quatre alertes, trois avaient une racine commune, et une non. Que quatre alertes apparaissent sur le même écran ne veut pas dire qu'elles ont une seule cause.

Une hypothèse écartée

Il y avait un suspect assez crédible. Le cron device-cleanup, qui tourne juste avant la rafale de 06:00, aurait provoqué de la contention de verrous. L'horaire collait, l'hypothèse était plutôt convaincante.

J'ai passé au peigne fin les logs des deux régions sur la fenêtre 05:30-06:15. Pas un seul log lié au cron. En vérifiant le chemin du Device.updateMany qui était lent, il ne s'agissait pas de la mise à jour en masse du cron mais de /v2/public/auth/refresh, c'est-à-dire d'une banale requête de rafraîchissement de token d'un utilisateur. L'hypothèse a été rejetée par la mesure. Que les horaires se chevauchent est une corrélation ; qu'il n'y ait rien dans les logs est un fait.

Nous avons replié les allers-retours

Deux voies s'offraient à nous. Endurer le symptôme : monter le timeout à 8 secondes, agrandir le pool, ajouter des retries. Ou supprimer le coût lui-même : réduire le nombre d'allers-retours.

Nous avons fait les deux. Passer la transaction de série sous withTxRetry est un pansement, mais c'était un pansement nécessaire. Le vrai remède, lui, était de replier les allers-retours.

L'outil existait déjà. Une migration du 27 juin contenait une fonction côté serveur nommée create_practice_attempt_v1. Elle replie le verrouillage de session, la lecture, l'insertion, la mise à jour des métadonnées de session et la lecture des agrégats précalculés dans une seule fonction SQL, bouclant le tout en un seul aller-retour. Elle est même idempotente (appelée deux fois avec le même client attempt id, le second appel renvoie la ligne existante et inserted=false).

Sauf que le feature flag qui active cette fonction, PRACTICE_ATTEMPT_SINGLE_RT_ENABLED, était à false par défaut et donc désactivé en production.

Plutôt que de supprimer une région ou de passer en actif-actif, ce que nous avons fait, c'est allumer un interrupteur déjà installé.

Le canari : sur quoi juger ?

Nous avons activé le flag uniquement en eu-west. us-east est resté éteint, comme groupe témoin. Passage de la task definition 786 à la 787, déploiement rolling.

Et c'est le choix de la métrique de jugement qui est le cœur de cette histoire. La latence est un piège. Déployez à une heure creuse et le p95 s'améliore même sans rien corriger. De fait, la latence s'est améliorée : le p50 est passé de 2 784 ms à moins de 2 000 ms. Mais c'est une preuve faible.

J'ai regardé le nombre de requêtes SQL par requête HTTP à la place.

avant   n=85   avg query_count = 22.0
apres   n=49   avg query_count = 15.3

Le nombre de requêtes SQL est une métrique par requête, indépendante de la charge. Que le trafic soit dense ou faible, c'est le chemin de code qui décide du nombre de requêtes émises pour une requête HTTP. De 22 à 15,3, soit environ 7 en moins. Et ces 7 correspondent exactement au nombre de requêtes de la liste que nous avions repliée dans une seule fonction (verrouillage de session + lecture + insertion + métadonnées de session + lecture des agrégats précalculés). La preuve que le chemin de code a réellement changé, c'est ce chiffre. Pas la latence.

L'échantillon après déploiement, c'est 49 requêtes sur 15 minutes. Dans cette fenêtre, il y a eu 0 erreur 5xx et 0 P2028, mais je n'ai pas mesuré en parallèle le nombre d'erreurs sur une fenêtre « avant déploiement » de même durée le même jour. Ce flag ne replie que l'enregistrement des tentatives. La transaction de série, elle, traverse toujours les régions. Que P2028 soit resté à 0 dans cette fenêtre-là veut dire que nous avons eu de la chance ; ce n'est pas une preuve.

Le déploiement a réussi, mais le flag a failli disparaître

Notre façon d'activer le canari avait un prix. La 787 est une task definition enregistrée à la main depuis la console. Au prochain déploiement officiel, le pipeline de CD l'écrasera par une task definition sans le flag. Ce n'est pas fatal (en cas d'écrasement, on retombe sur un OFF sûr). Simplement, l'amélioration disparaît en silence.

Il fallait donc la promouvoir dans terraform, et c'est là qu'est apparu le deuxième piège. Le workflow terraform n'applique que staging sur un push vers develop ; la production n'est appliquée que sur un push vers main. Or staging n'a tout bonnement pas de région eu-west. Autrement dit, merger dans develop une PR contenant un changement de production eu-west ne produit strictement rien. Il fallait changer la base pour main.

Il y avait un troisième piège. En mergeant directement dans main, develop prend du retard, et sans back-merge, la release suivante revert ce changement. Il a fallu ouvrir une PR de back-merge à part.

« Le terraform apply a réussi » et « c'est en production » sont deux phrases différentes.

Ce qu'il reste

Quand une alerte « DB down » arrive, il faut commencer par ouvrir les métriques de la base. Le nom d'une alerte est donné par le code qui la déclenche, pas par la cause. Notre health check disposait pourtant d'un pool dédié, isolé du pool applicatif, et il s'est quand même bouché avec l'app parce que le chemin vers la base était le même. Isoler, ce n'est pas seulement séparer les ressources : il faut aussi séparer les chemins.

Monter le timeout de 5 à 8 secondes fait taire les alertes du jour. Mais la requête traverse toujours l'Atlantique vingt-cinq fois. Que le trafic augmente un peu et 8 secondes ne suffiront plus. Mieux vaut décider à l'avance si l'on endure le symptôme ou si l'on supprime le coût. Si le coût s'écrit « nombre x distance », ce qu'il faut réduire, c'est le nombre.

La latence est ballottée par la charge, une métrique par requête ne l'est pas. Avant de se rassurer parce que le p95 s'est amélioré après un correctif de performance, il faut vérifier que le nombre de choses faites par une requête a réellement diminué. Ce chiffre-là est le même qu'on déploie à l'aube ou à midi.

J'ai compté le nombre d'allers-retours, et j'ai emprunté la latence par aller-retour à un commentaire de code. Ces deux commentaires disaient deux valeurs différentes. Heureusement, la conclusion n'a pas changé, mais la prochaine fois elle pourrait. Un chiffre qu'on n'a pas mesuré, écrivons qu'on ne l'a pas mesuré.