CPU synapse à 100% et lag
On observe depuis 1 semaine des passages de plus en plus fréquents du CPU de synapse à 100% et le serveur s'effondre progressivement. Il y a effectivement eu quelques vagues de spam suite au FOSDEM, mais on en est au stade où le trafic normal nous met par terre rapidement.
On a déjà creusé et j'ouvre cette issue pour capitaliser les réflexions et essayer d'identifier une piste de sortie correcte.
Activity
added Progression / En cours label
added Importance / Critique label
D'abord, les problèmes semblent souvent s'accumuler après une salve d'events, puis le serveur ne parvient plus à suivre la fédération pendant de nombreuses heures.
Exemple :
Toutefois, ce n'est pas le cas sytématiquement, par exemple :
Il y a donc probablement un état de fond qui affaiblit fortement le serveur (index mal optimisé, trop gros, etc.) et des épiphénomènes qui le mettent au tas.
-
Quelques requêtes pour explorer les coupables en nombre d'événéments.
Nombre d'événements par room et par heure, soit par heure de réception, soit par heure d'émission
select count(event_id), type, room_id, (received_ts/3600000)*3600 as ts from events where received_ts > 1643921432000 group by type, room_id, tsselect count(event_id), type, room_id, (origin_server_ts/3600000)*3600 as ts from events where origin_server_ts > 1643921432000 group by type, room_id, tsSur ces données, un simple sort pointe assez rapidement le coupable.
Evolution de l'écart entre émission et réception
select received_ts, received_ts - origin_server_ts from events where origin_server_ts > 1644477071000Matérialise le lag, mais aussi les salves d'events provenant de serveurs qui rejoignent la fédération après un temps. Exemple :
-
Plus que le simple monitoring de l'état du synapse ou des lags fédération, la taille de la queue de traitement des messages inbound semble être le meilleur critère pour identifier une difficulté. Un monitoring sur ce critère pourrait servir d'early alert (bien qu'on n'ait pas encore de solution pour rétablir) :
De même, pour matcher l'origine des défauts, on s'attache à observer les événements reçus dans ces périodes où la file de fédération commence à s'allonger, et le CPU monter en charge.
Matcher sur les performances d'envoi est bien moins pertinent, puisque l'état du serveur semble décourager les envois de messages, voire les pousser en erreur. Le taux d'erreur à l'envoi pourrait aider mais n'est qu'indirectement corrélé.
-
Pour profile synapse, on utilise
py-spyinstallé sur l'hôte et qui ptrace directement le processus conteneurisé.En temps normal, y compris sous charge élevée, l'essentiel de la charge est sur les fonctions d'accès à la bdd. Il y a probablement beaucoup d'optimisation de ce côté, notamment en maximisant l'emploi du cache. A creuser plus tard. Lorsque le serveur est vraiment indisponible, le profile devient intéressant :
Total Samples 9000 GIL: 100.00%, Active: 100.00%, Threads: 39 %Own %Total OwnTime TotalTime Function (filename:line) 100.00% 100.00% 90.00s 90.00s event_id (synapse/events/__init__.py:566) 0.00% 100.00% 0.000s 90.00s _run_module_as_main (runpy.py:194) 0.00% 100.00% 0.000s 90.00s run (synapse/metrics/background_process_metrics.py:242) 0.00% 100.00% 0.000s 90.00s _process_pulled_events (synapse/handlers/federation_event.py:636) 0.00% 100.00% 0.000s 90.00s runUntilCurrent (twisted/internet/base.py:964) 0.00% 100.00% 0.000s 90.00s run (twisted/internet/base.py:1315) 0.00% 100.00% 0.000s 90.00s <dictcomp> (synapse/state/__init__.py:439) 0.00% 100.00% 0.000s 90.00s _get_missing_events_for_pdu (synapse/handlers/federation_event.py:611) 0.00% 100.00% 0.000s 90.00s _check_for_soft_fail (synapse/handlers/federation_event.py:1486) 0.00% 100.00% 0.000s 90.00s _inlineCallbacks (twisted/internet/defer.py:1660) 0.00% 100.00% 0.000s 90.00s <module> (synapse/app/homeserver.py:472) 0.00% 100.00% 0.000s 90.00s _process_pulled_event (synapse/handlers/federation_event.py:689) 0.00% 100.00% 0.000s 90.00s _run_code (runpy.py:87) 0.00% 100.00% 0.000s 90.00s run (synapse/app/homeserver.py:447) 0.00% 100.00% 0.000s 90.00s resolve_events (synapse/state/__init__.py:439) -
Le synapse sous charge élevée, très actif sur la bdd a priori (a voir si c'est du wait ou de la charge) :
Total Samples 2095 GIL: 85.00%, Active: 530.00%, Threads: 39 %Own %Total OwnTime TotalTime Function (filename:line) 147.00% 270.00% 26.41s 37.34s _do_execute (synapse/storage/database.py:343) 76.00% 76.00% 7.99s 7.99s execute_values (psycopg2/extras.py:1270) 50.00% 50.00% 10.28s 10.28s commit (synapse/storage/database.py:176) 39.00% 39.00% 7.71s 7.71s untilConcludes (twisted/python/util.py:767) 25.00% 25.00% 1.90s 1.90s execute_values (psycopg2/extras.py:1267) 21.00% 21.00% 5.11s 5.11s _runWithConnection (twisted/enterprise/adbapi.py:283) 21.00% 21.00% 0.440s 0.440s recv (OpenSSL/SSL.py:1864) 15.00% 15.00% 2.32s 2.32s attempt_to_set_autocommit (synapse/storage/engines/postgres.py:189) 11.00% 11.00% 0.320s 0.320s execute_values (psycopg2/extras.py:1272) 10.00% 161.00% 0.110s 28.60s execute (synapse/storage/database.py:310) 5.00% 5.00% 0.070s 0.090s addCallbacks (twisted/internet/defer.py:481) 5.00% 5.00% 0.440s 0.440s execute_batch (psycopg2/extras.py:1187) 5.00% 5.00% 0.110s 0.110s _raise_ssl_error (OpenSSL/SSL.py:1673) 4.00% 4.00% 0.060s 0.060s __str__ (synapse/logging/context.py:335)Pour comparaison un synapse peu actif passe l'essentiel de son temps dans le reactor (ce qui est parfaitement normal pour un Twisted) :
Total Samples 200 GIL: 0.00%, Active: 100.00%, Threads: 22 %Own %Total OwnTime TotalTime Function (filename:line) 100.00% 100.00% 2.00s 2.00s poll (synapse/metrics/_reactor_metrics.py:48) 0.00% 100.00% 0.000s 2.00s run (synapse/app/_base.py:162) 0.00% 100.00% 0.000s 2.00s start_reactor (synapse/app/_base.py:178) 0.00% 100.00% 0.000s 2.00s _run_module_as_main (runpy.py:194) 0.00% 100.00% 0.000s 2.00s mainLoop (twisted/internet/base.py:1328) 0.00% 100.00% 0.000s 2.00s <module> (synapse/app/homeserver.py:472) 0.00% 100.00% 0.000s 2.00s run (synapse/app/homeserver.py:447) 0.00% 100.00% 0.000s 2.00s doPoll (twisted/internet/epollreactor.py:227) 0.00% 100.00% 0.000s 2.00s main (synapse/app/homeserver.py:468) 0.00% 100.00% 0.000s 2.00s run (twisted/internet/base.py:1315) 0.00% 100.00% 0.000s 2.00s _run_code (runpy.py:87) -
Le flamegraph a confirmé ce que les taux de requêtes donnaient déjà pas mal : le
get_users_in_roomeffondre pas mal en requête BDD.
Il avait un hit ratio en cache à 25% environ, et était trigger principalement par une super-transaction
get_users_in_same_room, qui avait un hit ratio à 30% elle-même. On a commencé par pousser le cache size de ces deux transactions d'un facteur 5 et 4 respectivement. Le hit ratio est >95% pour les deux dorénavant pour quelques dizaines de Mo de RAM.La charge CPU associée a chuté, on a pu rattraper la fédération. Cela a aussi mis en avant une nouvelle transaction qui mange des ressources. Peu fréquente, elle est excessivement longue d'exécution (plusieurs secondes voire dizaines de secondes par transaction). On observe comment ça se comporte à la prochaine salve de messages.
-
Après quelques heures de recul, effectivement la charge générale sur le serveur a diminué : il consomme 3 à 4 fois moins d'accès bdd en général, et 2 fois moins de CPU. En revanche même s'il met moins de temps à absorber s'en remettre, il continue de s'effondrer sur des événements spécifiques.
Le scénario est globalement le suivant :
- le serveur reçoit "quelque chose" (events entrants, sortants, on ne sait pas bien encore exactement)
- il monte immédiatement en charge CPU
- il cesse de traiter la fédération en contrepartie, ou beaucoup plus lentement
- la charge CPU descend mais la fédération reste très en retard, jusqu'à 1h ou 2h plus tard
- le retard est absorbé d'un coup, sans surcharge CPU énorme
On n'a pas de profil CPU pendant ces périodes pour l'instant. On va voir pour setup un profil toutes les 15 minutes à exploiter plus tard.
-
Pour générer un profil sur le pid
1234pendant 2 minutes à 25Hz et sans bloquer les threads :py-spy record --nonblocking -o record.txt -f raw -r 25 -d 120 -p 1234Puis on rappatrie le fichier raw et on le convertit en flamegraph sur le poste d'exploitation :
inferno-flamegraph < record.txt > flamegraph.svgLe flamegraph s'ouvre très bien dans Firefox en mode SVG interactif.
-
Expliquant je l'espère le nombre et la complexité des requêtes sur la chaîne d'authent d'une room en particulier :
matrix=> select room_id, count(*) c from event_forward_extremities group by room_id order by c desc limit 20; room_id | c ----------------------------------------------+----- !OOxKMCCXyQBnojCygy:synapse.travnewmatic.com | 255 !lcZfiDYVWwHkhobQaY:fachschaften.org | 7 !aUhETchlgthwWVQzhi:matrix.org | 7 !YTvKGNlinIzlkMTVRl:matrix.org | 4 !ioILbqRhHRKhIWGNJq:glowers.club | 3 !gbbBhDoyblLPLiZcAw:tedomum.net | 3 !OMBdwmVXiBvjFJkBUg:fosdem.org | 3Le delete de la room en question est en cours puisqu'elle a été remplacée :
synadm GET 'v1/rooms/!OOxKMCCXyQBnojCygy:synapse.travnewmatic.com' | jq { "room_id": "!OOxKMCCXyQBnojCygy:synapse.travnewmatic.com", "name": "LEGACY - Spite – Please move to the new room", "canonical_alias": "#general:spitetech.com", "joined_members": 2479, "joined_local_members": 2, "version": "5", "creator": "@analogpathy:synapse.travnewmatic.com", "encryption": null, "federatable": true, "public": false, "join_rules": "public", "guest_access": "can_join", "history_visibility": "world_readable", "state_events": 25014, "avatar": "mxc://matrix.org/nPhBKHGlkpeSNoldkuqCFErJ", "topic": "This is the legacy room for Spite. Please leave and join #general:spitetech.com.", "joined_local_devices": 6 }Commande pour le delete :
synadm DELETE 'v2/rooms/!OOxKMCCXyQBnojCygy:synapse.travnewmatic.com' -d '{"purge":true,"message":"This room was replaced following spam issues, please join #general:spitetech.com.", "block": true}'Problème pour le moment (usernames masqués) :
{ "results": [ { "delete_id": "sRcobqpWnOvYIcYE", "status": "failed", "shutdown_room": { "kicked_users": [], "failed_to_kick_users": [ "@xxx:tedomum.net", "@xxx:tedomum.net" ], "local_aliases": [], "new_room_id": null }, "error": "400: Users are still joined to this room" } ]Dans les logs synapse :
synapse_1 | 2022-02-13T13:46:43.658264589Z 2022-02-13 13:46:43,656 - synapse.handlers.room - 1655 - ERROR - shutdown_and_purge_room-3 - Failed to leave old room and join new room for '@xxx:tedomum.net' synapse_1 | 2022-02-13T13:46:43.658290524Z Traceback (most recent call last): synapse_1 | 2022-02-13T13:46:43.658295503Z File "/usr/local/lib/python3.8/site-packages/twisted/internet/defer.py", line 1660, in _inlineCallbacks synapse_1 | 2022-02-13T13:46:43.658299590Z result = current_context.run(gen.send, result) synapse_1 | 2022-02-13T13:46:43.658302995Z StopIteration: 0 synapse_1 | 2022-02-13T13:46:43.658306278Z synapse_1 | 2022-02-13T13:46:43.658309726Z During handling of the above exception, another exception occurred: synapse_1 | 2022-02-13T13:46:43.658315146Z synapse_1 | 2022-02-13T13:46:43.658320088Z Traceback (most recent call last): synapse_1 | 2022-02-13T13:46:43.658323823Z File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room.py", line 1639, in shutdown_room synapse_1 | 2022-02-13T13:46:43.658327391Z await self.room_member_handler.forget(target_requester.user, room_id) synapse_1 | 2022-02-13T13:46:43.658330801Z File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room_member.py", line 1767, in forget synapse_1 | 2022-02-13T13:46:43.658334795Z raise SynapseError(400, "User %s in room %s" % (user_id, room_id)) synapse_1 | 2022-02-13T13:46:43.658338191Z synapse.api.errors.SynapseError: 400: User @xxx:tedomum.net in room !OOxKMCCXyQBnojCygy:synapse.travnewmatic.com synapse_1 | 2022-02-13T13:46:53.305749122Z 2022-02-13 13:46:53,305 - synapse.handlers.room - 1655 - ERROR - shutdown_and_purge_room-3 - Failed to leave old room and join new room for '@xxx:tedomum.net' synapse_1 | 2022-02-13T13:46:53.305782076Z Traceback (most recent call last): synapse_1 | 2022-02-13T13:46:53.305787195Z File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room.py", line 1639, in shutdown_room synapse_1 | 2022-02-13T13:46:53.305791303Z await self.room_member_handler.forget(target_requester.user, room_id) synapse_1 | 2022-02-13T13:46:53.305794813Z File "/usr/local/lib/python3.8/site-packages/synapse/handlers/room_member.py", line 1767, in forget synapse_1 | 2022-02-13T13:46:53.305798244Z raise SynapseError(400, "User %s in room %s" % (user_id, room_id)) synapse_1 | 2022-02-13T13:46:53.305801730Z synapse.api.errors.SynapseError: 400: User @xxx:tedomum.net in room !OOxKMCCXyQBnojCygy:synapse.travnewmatic.com synapse_1 | 2022-02-13T13:46:53.307165126Z 2022-02-13 13:46:53,306 - synapse.handlers.pagination - 648 - ERROR - shutdown_and_purge_room-3 - failed synapse_1 | 2022-02-13T13:46:53.307198359Z Traceback (most recent call last): synapse_1 | 2022-02-13T13:46:53.307204201Z File "/usr/local/lib/python3.8/site-packages/synapse/handlers/pagination.py", line 638, in _shutdown_and_purge_room synapse_1 | 2022-02-13T13:46:53.307208012Z raise SynapseError( synapse_1 | 2022-02-13T13:46:53.307211272Z synapse.api.errors.SynapseError: 400: Users are still joined to this room added Progression / Fait label and removed Progression / En cours label
mentioned in commit ac8c9ac5
