Lenteurs et timeouts sur le cluster Garage
Depuis près de deux semaines, nous avons constaté (par remontée utilisateur principalement) des lenteurs et des défauts (erreurs 503 dues à des timeouts) sur le HTTP et sur le S3 de garage (à la fois en récupération et en upload d'image sur Mastodon notamment).
Perte du noeud bambino
Le premier niveau d'étude du problème a montré que seuls deux noeuds étaient disponibles sur le cluster. Pour cause : le serveur derrière bambino était éteint depuis le 23/06, probablement pour cause de capteur de température (refroidissement passif sur la machine, 34-35°c ambiant).
kubernetes avait pris le relais sur les services, et garage fonctionnait plutôt bien sur 2 noeuds. La machine a été redémarrée le 30/06 à 18h30 CEST, sans problème particulier. Le tranquility garage a été abaissé pour favoriser le resync, qui s'est achevé le 2/07 à 5h30 CEST environ.
Americancurl en pointillés
La supervision americancurl montre des points de mesure éparses pour Garage mais pas pour le node exporter. Ceci semble indiquer un souci lié au cluster garage, quelle qu'en soit l'origine.
Le noeud montre un fort niveau d'iotime :
Sur des prises de mesure en volume io, pour autant il y a raisonnablement peu de lecture ou écriture, ici sur 5 minutes en accumulé :
On constate par périodes (toutes les quelques dizaines de secondes) que l'API garage, le S3 et le Web sont incapables de répondre aux requêtes immédiatement depuis ce noeud précisément. Ce qui explique les trous dans les métriques, ainsi que les erreurs continues malgré le retour du cluster à 3 noeuds.
Dans ces cas, les endpoints finissent par répondre, mais avec un délai notable :
curl -v > /dev/null 0.16s user 0.05s system 0% cpu 2:03.98 total
curl -v localhost:3903/metrics 0.00s user 0.02s system 0% cpu 1:00.80 totalConstaté plusieurs fois avec exactement 2 minutes, ou exactement 1 minute.
Les logs de garage sur le noeud sont évocateurs également : pas d'activité pendant l'attente, puis de nombreuses requêtes loggées immédiatement. Souvent, après l'attente, un warning particulier est loggé :
garage 2023-07-02T11:30:44.711211Z WARN garage_api::generic_server: Response: error 500 Internal Server Error, Internal error (Hyper error): error reading a body from connection: Connection reset by peer (os error 104)Après la reprise le trafic est normal quelques dizaines de secondes, et le noeud lance plusieurs resyncs de blocs, avant de planter à nouveau.
Activity
Pendant le temps où le noeud americancurl est en défaut, les autres constatent bien un défaut de réponse, y-compris sur le RPC a priori :
garage 2023-07-02T11:30:41.746489Z ERROR garage_util::background::worker: Error in worker block_ref GC (TID 32): in try_send_and_delete in table GC: garage GC: send tombstones garage Could not reach quorum of 2. 1 of 2 request succeeded, others returned errors: ["Netapp error: Not connected: xxxxxxxxx"]-
Logs de bambino sur le cluster de test, qui ne génère normalement aucune io pour de la lecture ou écriture de blocs :
garage 2023-07-02T11:30:31.808268Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.815648Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.822816Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.829907Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.837205Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.844637Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.852019Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.859065Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.866299Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.873121Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.880279Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.887466Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.894581Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.901931Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.909379Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.916364Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.923208Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.930386Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.937719Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.944907Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.952175Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.960922Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.969893Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.977068Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.984201Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.991150Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:31.998517Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.005441Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.012918Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.020021Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.027266Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.034109Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.041289Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.048421Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.055601Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.063233Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.070361Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.077223Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.084188Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.091034Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.097961Z WARN garage_table::sync: (version) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.104282Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.117865Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.125035Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.132395Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.139675Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.146660Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.153710Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.161212Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.168686Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.176337Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.184301Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.191707Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.199354Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.206911Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.214644Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.222446Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.230353Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.238057Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.245716Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.253577Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.261014Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.319132Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.326743Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.334231Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.341957Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.349772Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.357260Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.364760Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.371899Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.379292Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.386837Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.394838Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.402866Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.459755Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.467162Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.474386Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.481640Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.488960Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.496409Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.504032Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.511669Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.519036Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.526161Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.533543Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.541116Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.548718Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.556414Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.564294Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.571683Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.579127Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.586271Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.593431Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.600737Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:30:32.608097Z WARN garage_table::sync: (block_ref) Sync error: Netapp error: Not connected: 9221ed752ca612d3 garage 2023-07-02T11:34:17.206994Z INFO garage_rpc::system: Doing a bootstrap/discovery step (not_configured: false, no_peers: false, bad_peers: true) garage 2023-07-02T11:34:17.421718Z ERROR garage_rpc::system: Failed to create kubernetes custom resource: ApiError: Apply failed with 1 conflict: conflict with "kubectl-client-side-apply" using apiextensions.k8s.io/v1: .spec.versions: Conflict (ErrorResponse { status: "Failure", message: "Apply failed with 1 conflict: conflict with \"kubectl-client-side-apply\" using apiextensions.k8s.io/v1: .spec.versions", reason: "Conflict", code: 409 }) garage 2023-07-02T11:34:17.480488Z INFO garage_rpc::kubernetes: Found Pod: Some("9221ed752ca612d327afb5be5a57a25c4366a4991859790e159b72fc8d3793b1") garage 2023-07-02T11:34:17.480510Z INFO garage_rpc::kubernetes: Found Pod: Some("1fab23af95d8e30075c184e1179d4da395c7405724946cad810ea0afc47f9b21") garage 2023-07-02T11:34:17.480520Z INFO garage_rpc::kubernetes: Found Pod: Some("bed6b7ea1f11c919eff8f5c1676411cf76b2e4a6374fe5aa5c3b8fa3ee45446f") Stream closed EOF for tedomum-tests/garage-xzpl9 (garage-init) -
Pendant les phases down, on note une différence de comportement selon la source des requêtes :
- Depuis le Web, aucune requête n'est répondue
- A travers l'apiserver en port-forward, aucune requête n'est répondue
- Depuis des pods sur tous les noeuds, les requêtes sont répondues sur le /metrics par exemple
- Depuis l'apiserver directement (sans port-forward), aucune requête n'est répondue
L'ICMP vers le pod garage, ou les connexions vers d'autres process qui tournent sur le même hôte ne posent pas de problème alors même que les requêtes garage sont bloquées.
Quand plusieurs requêtes sont lancées en parallèle, elles aboutissent toutes en même temps. Le comportement ressemble à un blocage côté garage ou système, qui bloque les requêtes, entraint une accumulation de requêtes inflight, qui augmente le nombre de threads tokio côté garage, tous bloqués, et augmente donc progressivement le load average. Lorsque ça débloque, tout est répondu, le LA instantané retombe très rapidement bas.
Edited by kaiyou -
Tentative de capture d'une requête vers le
/doesnotexistdu garage problématique, depuis l'apiserver qui émet la requête d'un côté, depuis le noeud où est le garage de l'autre. Une requête problématique vue de part et d'autre : aucun indice de défaut réseau côté client ou serveur.No. Time Source Destination Protocol Length Info 262 *REF* 10.50.0.1 10.21.2.131 TCP 60 14089 → 3903 [SYN] Seq=0 Win=65280 Len=0 MSS=1280 SACK_PERM TSval=7052379 TSecr=0 WS=128 263 0.002686 10.21.2.131 10.50.0.1 TCP 60 3903 → 14089 [SYN, ACK] Seq=0 Ack=1 Win=64668 Len=0 MSS=1280 SACK_PERM TSval=3907639448 TSecr=7052379 WS=128 264 0.002743 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=1 Ack=1 Win=65280 Len=0 TSval=7052382 TSecr=3907639448 265 0.002829 10.50.0.1 10.21.2.131 HTTP 207 GET /doesnotexist HTTP/1.1 266 0.005884 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [ACK] Seq=1 Ack=156 Win=64640 Len=0 TSval=3907639451 TSecr=7052382 267 130.805263 10.21.2.131 10.50.0.1 HTTP/JSON 318 HTTP/1.1 400 Bad Request , JavaScript Object Notation (application/json) 268 130.805326 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183184 TSecr=3907770250 269 130.806836 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [FIN, ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183185 TSecr=3907770250 270 130.836215 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [FIN, ACK] Seq=267 Ack=157 Win=64640 Len=0 TSval=3907770281 TSecr=7183185 271 130.836249 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=157 Ack=268 Win=65024 Len=0 TSval=7183215 TSecr=3907770281No. Time Source Destination Protocol Length Info 1276 *REF* 10.50.0.1 10.21.2.131 TCP 60 14089 → 3903 [SYN] Seq=0 Win=65280 Len=0 MSS=1280 SACK_PERM TSval=7052379 TSecr=0 WS=128 1277 0.000058 10.21.2.131 10.50.0.1 TCP 60 3903 → 14089 [SYN, ACK] Seq=0 Ack=1 Win=64668 Len=0 MSS=1280 SACK_PERM TSval=3907639448 TSecr=7052379 WS=128 1278 0.002700 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=1 Ack=1 Win=65280 Len=0 TSval=7052382 TSecr=3907639448 1279 0.002947 10.50.0.1 10.21.2.131 HTTP 207 GET /doesnotexist HTTP/1.1 1280 0.002977 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [ACK] Seq=1 Ack=156 Win=64640 Len=0 TSval=3907639451 TSecr=7052382 1341 130.802996 10.21.2.131 10.50.0.1 HTTP/JSON 318 HTTP/1.1 400 Bad Request , JavaScript Object Notation (application/json) 1352 130.805458 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183184 TSecr=3907770250 1360 130.807532 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [FIN, ACK] Seq=156 Ack=267 Win=65024 Len=0 TSval=7183185 TSecr=3907770250 1392 130.833810 10.21.2.131 10.50.0.1 TCP 52 3903 → 14089 [FIN, ACK] Seq=267 Ack=157 Win=64640 Len=0 TSval=3907770281 TSecr=7183185 1394 130.836460 10.50.0.1 10.21.2.131 TCP 52 14089 → 3903 [ACK] Seq=157 Ack=268 Win=65024 Len=0 TSval=7183215 TSecr=3907770281Edited by kaiyou -
Tests d'écriture sur le disque externe vs. le disque interne, pour tester l'état de la stack io et du disque lui-même. On écrit 1ko, puis 100ko en 100 séquence fsync de 1ko.
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 26.11s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.19s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.28s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 4m 15.84s# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync real 1m 5.89sPuis sur le stockage interne :
# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync real 0m 0.09s # time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync real 0m 0.09s # time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync real 0m 0.07s # time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=1 conv=fsync real 0m 0.09s# time dd if=/dev/zero of=/host/root/testwrite bs=1024 count=100 conv=fsync real 0m 0.11s -
Une fois garage arrêté, je relance le même de fsync de 1ko en 1 fois, 100 fois, 10000 fois (10Mo) :
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.21s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.50s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.56s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.65s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.06s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.20s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.08s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=1 conv=fsync real 0m 0.05s# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync real 0m 0.20s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync real 0m 0.51s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync real 0m 0.67s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=100 conv=fsync real 0m 0.76s# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=10000 conv=fsync real 0m 0.69s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=10000 conv=fsync real 0m 1.60s # time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1024 count=10000 conv=fsync real 0m 0.31sEt poussé jusqu'à 1Go par blocs de 1Mo pour tester le débit global :
# time dd if=/dev/zero of=/host/hdd/debug/testwrite bs=1M count=1024 conv=fsync real 0m 28.35sCe qui donne un 300Mbps, pas fou mais honorable pour un disque USB.
-
De façon très intéressante, je constate des performances io dégradées également sur les autres noeuds.
Sur cyprus :
# time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync real 0m4.942s # time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync real 0m1.705s # time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync real 0m2.087s # time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=1 conv=fsync real 0m2.103s # time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=100 conv=fsync real 0m1.345s # time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1024 count=100 conv=fsync real 0m1.711s # time dd if=/dev/zero of=/mnt/ted1/debug/testwrite bs=1M count=1024 conv=fsync 1073741824 bytes (1.1 GB, 1.0 GiB) copied, 75.472 s, 14.2 MB/s real 1m15.475sLes performances USB sont significativement inférieures à la normale, le fsync lui-même est particulièrement lent.
added progress::working label
added level::critical topic::infra type::bug labels
-
Résumé de nos derniers progrès sur le sujet.
De nombreuses tentatives n'ont pas résolu le défaut, qui est en partie amplifié par le comportement de Stoplight côté Mastodon, bloquant en amont les requêtes vers le backend, avec du backoff, lorsqu'une erreur est remontée par Garage. Concrètement, après 10 ou 20 erreurs, le backend est désactivé pendant plusieurs minutes avant de réessayer. Lorsqu'il réessaie il relance aussi toutes les tâches en attente et bombarde donc le backend, qui s'effondre, etc.
Quatre actions ont été menées avant-hier et hier pour essayer d'améliorer (avec un résultat positif, mais pas suffisant) :
- basculer les metadata de
cyprussur le SSD qui sert aussi à l'OS plutôt que l'USB externe ; - diriger toutes les requêtes entrantes garage vers
cyprus, les autres noeuds servant de standby à ce stade - désactiver finalement à nouveau
americancurlqui générait un maximum de timeouts puisque dans un état encore pire que la semaine dernière - stopper les tâches planifiées qui nettoient les media Mastodon et généraient plusieurs
DELETEpar seconde sur le S3 quand elles tournaient
Déjà on vois bien quand on retire americancurl du cluster l'effet sur les IOs
Les deux pods garage sont sur bambino et cyprus, le premier est à 100% d'IO (avec 300% d'oversuscribe) et le second est à 30% seulement. Ce qui peut s'expliquer par la bascule des meta de
cyprussur du SSD.Max a passé la tranquility du scrub et du resync à 20, et descendu le nombre de worker à 1 - on va voir si ça fait baisser la charge IOPS. Une explication plausible est que la quantité de blocs en resync, même avec une tranquility élevée, génère un grand nombre de retry et requeue, qui écrivent chacun des metadata et entraînent du write continu sur le LMDB.
Comparaison entre Cyprus et Bambino (on voit bien le passage sur SSD sur Cyprus et le 4/07 où le disque de Bambino commence à saturer en IO) :
- basculer les metadata de
-
Prochaines actions entreprises :
- Basculer les meta de
bambinosur SSD, il y a de la place disponible pour ça - Installer du SSD sur americancurl, ticket séparé à ouvrir
- Investiguer si c'est bien le resync qui génère du bruit IO, auquel cas il faudrait d'une part améliorer le comportement de garage, d'autre part diminuer la taille de la resync queue
- Basculer les meta de
-
Avec kity#17 (closed), americancurl est rétabli en full flash, donc avec les meta sur flash.
On observe sur les jours à venir la métrologie garage pour confirmer l'intuition : que le raccourcissement de la resync queue s'accompagne d'une diminution des RPC au sein du cluster et d'une diminution des IO sur les meta liées au requeue de 300k blocs en boucle.
Si tel est le cas, on réfléchira à comment améliorer garage, au minimum la documentation, pour expliquer ce type de phénomène : quand un noeud commence à traîner, voire est déconnecté, l'allongement progressif de la resync queue a un impact croissant sur en IO de meta sur les autres noeuds, ce qui peut finir par effondrer complètement le cluster. La configuration du tranquility ne semble pas suffire à limiter cet impact dans le temps.
-
Petite interprétation consolidée des faits en guise de RFO.
Timeline
Pour les pressé•e•s :
- 22/06 extinction de
bambinosans que nous en ayons connaissance - 27/06 premier signalement, pas pris comme un incident
- 29/06 détection de l'arrêt de
bambino - 30/06 redémarrage de
bambino - 1/07 début des investigations sur
americancurl - 2/07 généralisation du défaut, début d'incident
- 2/07 sortie de
americancurldu clustergarage - 3/07 début des investigations approfondies
- 6/07 bascule des metadata
garagedecyprussur SSD - 8/07 attribution du défaut à la queue de resynchronisation
garagedans nos conditions d'IO - 8/07 bascule des metadata
garagedebambinosur SSD, service rétabli - 8/07 achat d'un SSD 4To pour réintégrer
americancurl - 10/07 livraison du SSD pour
americancurl - 13/07 installation du nouveau SSD
- 14/07 réinstallation de
americancurl - 15/07 réintégration de
americancurldans le cluster
Début d'incident
Nous ne conservons pas la métrologie par défaut assez longtemps pour remonter au début de l'incident, donc nous n'avons pas de report exact, mais plusieurs retours via Matrix et Mastodon nous ont mis la puce à l'oreille.
Le 27/06 probablement le premier retour :
Bonsouiiiiinr Est-ce qu’une difficulté à envoyer des médias sur MastoTedomum est de mon côté, ou c’est côté instance ? Bon courage pour tout
Genre une 503.
Le problème n'étant à l'époque pas général, il a mis bien plus de temps à être considéré comme un véritable incident et pas un défaut isolé dû à un restart de service ou une lenteur passagère.
La concomitance avec un incident sur Matrix impactant la cryptographie de bout en bout a encore plus masqué le défaut à nos yeux. Le problème est devenu critique le 2/07, soit 5 jours plus tard, lorsque le noeud le plus impactant dans le défaut -
americancurl- a commencé à perdre sérieusement pied.Causalité générale
Un défaut détaillé plus loin, lié vraisemblablement à la gestion de la resynchronisation des blocs et aux IO limitées sur nos disques durs de l'infrastructure, a commencé à ralentir notre cluster
garage, solution de stockage compatible S3. S3 est un standard pour le stockage d'objets sur le Web, le cluster en question stocke par exemples toutes les pièces-jointes Mastodon et vidéos Peertube de TeDomum.C'est un cluster à 3 noeuds, configuré pour nécessiter 2 noeuds fonctionnels à tout moment et donc pouvoir en perdre un. La situation est toutefois toute autre lorsque le défaut n'est pas franc. Dans ce cas, les performances peuvent être fortement diminuées, ce que nous avons constaté : des requêtes vers le cluster qui durent 10 secondes à 2 minutes dans une situation où un noeud était franchement indisponible, puis revenu, et un autre noeud avec un défaut de disque dur.
Mastodon a été le service le plus impacté. Il est configuré pour utiliser notre cluster
garagecomme stockage S3. Mastodon emploie la bilbiothèque Paperclip pour le stockage S3, qui elle-même s'appuie sur la bibliothèque Stoplight pour gérer les défauts éventuels du stockage en arrière-plan. Lorsqu'un toot est reçu avec une image, le texte est stocké en base de données, puis une tâche planifiée récupère l'image depuis l'instance d'origine et la stocke dansgaragepour la mettre ensuite à disposition. Ce décalage explique que très ponctuellement des images puissent être affichées comme indisponibles par Mastodon : le toot est là, mais pas encore l'image.Dans le cas présent, les requêtes vers
garageprenant parfois jusqu'à 2 minutes, elles étaient automatiquement interrompues par Mastodon par un timeout à 1 minute. A chaque échec, Stoplight mémorise le défaut du service de stockage et place automatiquement les suivantes en échec, si bien que quelques échecs éparses (c'était le cas au début) peuvent avoir un effet en salves d'images non disponibles. Pire, le comportement allonge la durée de blocage lorsque les échecs se multiplient.Au plus difficile de l'incident, c'est-à-dire les 7-8 juillet, 90% des images étaient en échec.
Cause racine
Un défaut d'IO sur
americancurla possiblement été déclenché par un défaut surbambinoet a entraîné un défaut général sur le cluster.Défaut de bambino
Très simplement,
bambinoa été éteint du 22 juin au 30 juin. Il s'est éteint très vraisemblablement à cause d'une élévation de température (> 30° dans l'environnement et ventilation perfectible dans le meuble) et d'un déclenchement de la sécurité sur sa carte mère.L'extinction de la machine n'a été détectée que le 29 juin car elle hébergeait uniquement un noeud
garageet la résilience native du cluster avait presque complètement masqué le défaut.Défaut de americancurl
Le noeud semble avoir commencé à défaillir suite à un défaut d'IO sur son disque de stockage, connecté en USB3 en externe. Le transfert de données a montré une limite à 10Mo/s sur ce disque. Hors en l'absence de
bambinoil a reçu mécaniquement 50% de requêtes en plus et probablement atteint ses limites.Après plusieurs tests, captures réseau et captures syscalls, nous avons déterminé qu'un défaut des IO sur le noeud, notamment des IO en attente dans une routine asynchrone de
garage, causait l'indisponibilité de l'ensemble du processus et de ses interfaces : toute requête, y-compris sur les API d'administration était bloquée, de même que sitokio, la bibliothèque d'IO asynchrone employée pargarageétait bloquée.Nous pensons que ce comportement a agravé l'impact en allongeant les durées de requêtes et en excluant régulièrement le noeud du cluster car il ne répondait plus assez vite. Ainsi, lorsque
americancurlétait exclu du cluster alors que nous n'avions pas encore rétablibambino, le dernier noeud seul ne pouvait plus accepter de requête en écriture.Ce défaut reste à isoler dans le code, il a été traité brutalement en isolant
americancurldu cluster une foisbambinorétabli.Défaut du cluter
La cause racine est incertaine à ce stade. Notre meilleure piste reste un effet boule de neige liée à la queue de resynchronisation de
ŋarage.Dans son comportement interne,
garagestocke les objets découpés en blocs, les blocs sont répliqués en asynchrone entre les noeuds, par un mécanisme de synchronisation. En cas d'erreur, les blocs à resynchroniser sont placée dans une queue pour ré-essayer. Cette queue est stockée dans une table de métadonnée (format LMDB sur notre instance).A intervalle régulier (allégé par un mécanisme de traquility),
garageretente la synchronisation des blocs en attente, puis les replace dans la queue si l'erreur persiste.Lorsqu'un noeud ne parvient plus à suivre le trafic du cluster pour quelque raison (par exemple celles évoquées puis haut pour
americancurl), alors les synchronisations de blocs échouent et les autres noeuds ajoutent tous les nouveaux blocs à la queue de resynchronisation, et les retentent en boucle.Lorsque le nombre de blocs en queue (jusqu'à plus de 300000 dans notre cas) est trop important, la quantité d'IO en écriture liée à la sortie de queue et réinsertion est telle qu'elle effondre les performances du stockage, encore une fois en USB3 externe sur les noeuds du cluster, même sur des disques avec de bonnes performances.
Ce comportement a été intensifié par les tâches de nettoyage de média Mastodon qui suppriment des objets et ont rajouté encore à la queue.
Actions entreprises
D'abord, rien
Les premiers jours du défaut, nous n'avons d'abord pas pris la situation au sérieux. Le défaut était localisé sur
americancurlunqiuement et pas encore assez critique pour être visible généralement.Remise en route de
bambinoBambino a été détecté hors ligne le 29 juin suite à une consultation des métriques.
Le défaut a été confirmé le 30 juin sur place, et
bambinoa redémarré immédiatement.Le 1er juillet
bambinoavait fini de rattraper son retard sur le cluster, nous donnant espoir que le défaut était corrigé.Isolation de
americancurlEn suivant les métriques
garagepour la reconstruction debambinonous avons détecté queamericancurlpeinait à répondre aux requêtes et commencé à investiguer sur ce noeud le 1er juillet.Par exemple le graphe de fin de resynchronisation avec
bambinomontre des métriques à trous, lorsque l'API ne répond plus :
Le 2 juillet, munis de captures réseau, de captures syscalls, d'analyse des statistiques d'IO détaillées sur la machine, nous avons creusé ce défaut de
americancurl.Nous avons conclu à un défaut d'IO, réseau ou stockage, en misant « probablement stockage ». Nous avons également identifié le comportement de
garagequi freeze globalement, identifié que la prochaine version permettrait de supprimer la dépendance auxfsyncqui pourrait améliorer ce défaut.Finalement en fin de journée nous avons déconnecté
americancurldu cluster dans l'espoir de réablir un comportement correct. Les requêtes étaient à nouveaux plutôt correctement servies, avec toujours des défauts, en nombre croissant.Identification du problème de resynchronisation
Le premier constat a été mené le 3 juillet : le taux d'IO continuait d'augmenter, y-compris sur les noeuds. Les IO approchaient les 100% sur les 2 noeuds.
Une partie s'expliquait par plus de requêtes sur 2 noeuds que sur 3, mais pas uniquement. Le taux d'IO a rapidement été isolé le 4 juillet comme des écritures sur les metadata, sans justifier de pourquoi le LMDB était particulièrement chargé.
Le 7 juillet, l'impact sur Mastodon a été confirmé avec la compréhension que le défaut était lié aux écritures S3 en échec et non aux lectures, et à Stoplight qui amplifiait l'impact.
Une première piste a été ouverte pour instrumenter
garageavectokio-console, piste qui n'a pas abouti à ce jour.Le 8 juillet, la meilleure piste identifiée était la queue de resynchronisation, qui a donné lieu à une résolution.
Basculer le stockage des meta sur flash
Dès le 2/07, sous l'hypothèse que le problème sur
americancurlétait lié aux IO, nous avons envisagé de remplacer le stockage de la machine, et évoqué les alternatives en fonction du nombre de slots disponibles.Le 6/07, constatant que le problème était global sur le cluster et sans piste de résolution à court terme, nous avons commencé à évoquer de basculer partiellement ou totalement sur du stockage flash pour augmenter les performances au moins d'écriture sur les meta garage.
Cette démarche peut sembler contre-intuitive : il faut plutôt résoudre le problème racine qui génère les IO. Pour autant et pour d'autres usages nous savons que nous devrons déployer du flash d'ici 1 an. Le fil de messages kity#17 (closed) a été ouvert pour approfondir ce sujet.
Plus tard dans la journée du 6/07 nous avons fait l'hypothèse (fausse) que les reads random étaient à l'origine de la pression IO et migré les métadonnées
garagedecyprusdepuis le stockage rotatif USB3 vers le SSD interne qui sert également à l'OS, au moins de façon temporaire. Cela n'a pas résolu franchement le problème puisquebambinotraînait toujours derrière.Le 8/07 nous avons confirmé la présence de place SSD suffisante sur
bambinopour migrer de même les métadonnées sur le même support que l'OS, ce que nous avons fait dans la journée. Cette intervention a rétabli des performances normales côté Mastodon, et le service est resté fonctionnel jusqu'à maintenant.Plus tard le 8/07, pour préparer la réintégration de
americancurlnous avons planifié une coupure complète du noeud pour vérifier les slots, constaté un seul SATA3 interne utilisé pour l'OS, et pris la décision d'acheter 4To de SSD en SATA3.Le SSD de
americancurlétait reçu le 10/07, installé le 13/07 :
Après quelques corrections dues à une montée de version de Debian 10 à Debian 12, puis rollback à ce stade vers Debian 11,
americancurlest donc à nouveau dans le cluster.Réintégrer un noeud
Réintégrer un noeud
garageaprès plusieurs semaines d'interruption et donc une queue de resynchronisation était un exercice intéressant, et la métrologie collectée est préciseuse, donc capitalisée à suivre.Le noeud a rejoint le cluster officiellement à 10h39 le 15/07 :
Ca a l'air ok, je réactive garage sur americancurl YOLO.
Le premier effet était une très forte charge IO, CPU et réseau due à la synchronisation des tables de métadonnées avec le reste du cluster :
Quelques instants plus tard, les blocs ont commencé à resynchroniser (aidés par une tranquility abaissée à 0 pendant la resynchronisation). Environ 3h plus tard la resynchronisation était terminée et la taille de la queue de resynchronisation retombée, de même que le nombre de blocs en erreur.
Pendant ce temps, les RPC du block manager - à un niveau croissant lentement et globalement élevé, interprété comme du requeue systématique les jours précédent - ont d'abord doublé pendant la resynchronisation, puis sont retombées à un niveau très bas.
Le taux global de RPC à plus de 100/s est reombé à max 10/s.
Plus surprenant, les IO disques elles-mêmes ont suivi un pattern en deux temps : d'abord pendant la resynchronisation les IO ont explosé, tout-à-fait supportées par les SSD puisque les principales écritures sont sur le full flash de
americancurl. Puis elles se sont restabilisées, à un niveau équivalent en écriture et un niveau supérieur en lecture à la situation précédente.
En approfondissant par noeud, sur
americancurlle comportement est classique : il a d'abord recopié les données (beaucoup de writes et reads) puis lancé un scrub (beaucoup de read constant). Puis il est revenu à un niveau très bas.
Sur
cyprus, les IO sont restées constantes pendant tout l'exercice.
Sur
bambinoen revanche, les IO ont augmenté significativement après.
Le comportement est possiblement perturbé du fait que pour les métriques saisies, seul
cyprusreçoit des requêtes Web et API. Depuis, l'ensemble des noeuds a réintégré le cluster et nous continuons d'observer. - 22/06 extinction de
added progress::tests label and removed progress::working label