perf problèmes
Voir le ticket dans sa version avant résolution
Depuis quelques temps, talk.felinn.org est considérablement lent (toutes les requêtes en front sont au dessus de 200ms, parfois 8000ms...)
Je viens de conclure une première investigation. A été fait/vérifié :
-
apt update & full-upgrade -
vérification de la connexion Redis et mise à jour du CT 110 -
désactivation des plugins Flarum pouvant affecter les performances -
retrait provisoire de la font IBM Plesk -
activation de opcache
dansphp-fpm
-
vérification des logs php, nginx & mysql (rien de concluant) -
redémarrage du CT et effaçage du cache de Flarum
Rien n'a amélioré la situation. Je penche pour un problème de configuration MariaDB. J'ai installé mysqltuner pour faire un audit. Comme entre temps j'ai redémarré MariaDB, ses résultats ne sont pas encore pertinents. Reste donc :
-
attendre quelques jours -
exécuter l'audit -
appliquer ses recommandations notamment dans my.cnf
Si rien n'y fait :
-
passer à Debian 11 -
passer à php 7.4 -
mettre à jour Flarum
Si rien n'y fait bis :
-
demander de l'aide sur discuss.flarum.org
En m'occupant de ce ticket j'ai pu faire une investigation intéressante concernant la gestion des bases de données avec ZFS, et sur l'état de l'IO de manière plus générale.
Résolution
front
- j'ai commencé par monitorer Flarum depuis l'onglet "réseau" de la console Firefox, cache désactivé, pour voir les transactions qui prenaient du temps
- le résultat est sans appel : il s'agit toujours des
XHR
qui permettent d’interagir avec l'API de Flarum, et non pas par exemple des assets (avatars, fonts, css), mais- c'est très aléatoire même si c'est régulier
- ce n'est jamais la même latence (même si en cas de lenteur, c'est toujours au dessus de 1s)
- partant de là, c'est ambigu : il peut y avoir un problème de JS en front ou un problème xyz en backend
- pour éliminer le problème de l'interaction avec le navigateur et du JS, je commence par récupérer une requête API lente dans la console Firefox et je l'exporte en requête au format cURL :
clique droit > copier > copier comme cURL
(hyper pratique, ça récupère les paramètresheader
et lestoken
nécessaires à l'authentification)- je me logue en SSH sur le serveur puis dans le LXC et je prépare la commande cURL en remplaçant
talk.felinn.org
parlocalhost
pour éliminer au passage l'hypothèse reverse-proxy - je rajoute
-w %{time_connect}:%{time_starttransfer}:%{time_total}
à la fin de la commande pour avoir le temps de connexion - je fais plusieurs tentatives jusqu'à recevoir une réponse lente
- je me logue en SSH sur le serveur puis dans le LXC et je prépare la commande cURL en remplaçant
À partir d'ici, on a déjà la confirmation que le problème est en backend : c'est la requête API en elle-même qui met du temps à répondre et rien d'autre. Comme la requête API est censée exécuter une requête SQL via un appel à PHP, j'ai deux possibilités : aller voir du côté de PHP ou aller voir ce que dit MariaDB quand on l'appelle.
PHP
Je commence par PHP vu que c'est lui qui est appelé en premier lors des requêtes. Côté Flarum (activation du debug dans config.php
), tout va bien. Alors je me souviens qu'entre PHP et SQL, il y a ce super truc développé par Nginx qui s'appelle php-fpm
et qui joue le rôle de chronopost© entre le code PHP de l'application et MariaDB. Je réalise alors que rien n'est spécialement optimisé de ce côté là :
- j'ajuste les règles des processus (
pm
) à l'aide des ce genre de billets de blog (sachant que je l'ai déjà fait sur Nextcloud donc je n'étais pas perdu) - j'active
OPcache
parce que ça ne coute pas grand chose et c'est recommandé - je redémarre le service
php-fpm
SQL
Rien n'y fait, les mêmes requêtes sont (aléatoirement) lentes, mais ce détour permet de resserrer fortement l'étau autour de MariaDB. Comme il n'y avait rien dans /var/log/mysql/error.log
je sais déjà qu'on n'est pas face à un vrai bug mais face à un problème de performance. À partir là ça devient rigolo :
- je commence par activer le log des
slow_query
, que je règle au passage sur 3s (par défaut c'est 10s mais faut pas pousser non plus, je ne suis pas sûr d'avoir déjà attendu 10 secondes un chargement de page) - je
tail
le log en question (attention, il est par défaut dans/var/lib/mysql
Je vais donc me balader sur le forum, et là mon log se remplit de choses comme ça :
# Time: 220117 14:34:15
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8828 Schema: flarum QC_hit: No
# Query_time: 3.097120 Lock_time: 0.000039 Rows_sent: 0 Rows_examined: 1
# Rows_affected: 1 Bytes_sent: 52
use flarum;
SET timestamp=1642426455;
update `flarumaccess_tokens` set `last_activity_at` = '2022-01-17 13:34:12', `last_ip_address` = '127.0.0.1', `last_user_agent` = 'curl/7.64.0' where `id` = 610;
# Time: 220117 14:34:20
# User@Host: flarum[flarum] @ localhost []
# Thread_id: 8828 Schema: flarum QC_hit: No
# Query_time: 4.324685 Lock_time: 0.000029 Rows_sent: 12 Rows_examined: 12
# Rows_affected: 0 Bytes_sent: 1005
SET timestamp=1642426460;
select * from `flarumpost_reactions` where `reaction_id` is not null and `flarumpost_reactions`.`post_id` in (910, 915, 935, 1125, 1156, 1627, 1630, 1644, 1647, 2530, 2554);
À noter que les SET timestamp
sont réalisés par le log lui-même
Comme l'a remarqué un comparse sur le forum de Flarum, on est sur quelque chose de pour le moins surprenant : de bêtes requêtes SELECT
peuvent être très poussives (>3 secondes). C'est très embêtant, et ça cache un problème de fond. L'étape suivante consiste à profiler une requête pour voir ce qui prend vraiment du temps dedans. Pour cela, il faut :
- activer le
profiling
- exécuter une requête en CLI jusqu'à tomber sur une répones lente
- afficher le profil (par défaut, le profil de la dernière requête est affiché)
Ici, j'ai exécuté une requête qui met à jour la date de dernière activité d'un user, soit le truc le plus simple pour Flarum :
MariaDB [flarum]> update `flarumusers` set `last_seen_at` = '2022-01-17 16:43:12' where `id` = 2;
Query OK, 1 row affected (2.028 sec)
Rows matched: 1 Changed: 1 Warnings: 0
MariaDB [flarum]> SHOW PROFILE;
+------------------------+----------+
| Status | Duration |
+------------------------+----------+
| Starting | 0.000074 |
| Checking permissions | 0.000009 |
| Opening tables | 0.000156 |
| After opening tables | 0.000012 |
| System lock | 0.000006 |
| Table lock | 0.000007 |
| Init for update | 0.000074 |
| Updating | 0.000134 |
| End of update loop | 0.000010 |
| Query end | 0.000005 |
| Commit | 2.026614 | <<< MAYDAY MAYDAY
| Closing tables | 0.000050 |
| Unlocking tables | 0.000016 |
| Closing tables | 0.000116 |
| Starting cleanup | 0.000015 |
| Freeing items | 0.000015 |
| Updating status | 0.000060 |
| Reset for next command | 0.000030 |
+------------------------+----------+
Il n'y a pas besoin de faire de longues recherches pour comprendre : le commit
correspond à l'étape d'écriture définitive des données affectées par le requête sur le disque. Or derrière cette étape cruciale de la transaction, il y a un bazarre bien orchestré qui porte le joli nom de InnoDB.
🔴
sous le capot de MariaDB InnoDB est un moteur de transaction et de stockage des données pour MariaDB très largement utilisé par moult applications web (Flarum et Nextcloud notamment). Son succès provient de sa capacité à assurer des transactions répondant au cahier des charges ACID (atomicité, cohérence, isolation et durabilité). Autrement dit, InnoDB c'est la garantie de livrer une lettre avec recommandé + accusé de réception + FOURGON BLINDÉ
Tiens tiens, ça ne vous dit pas quelque chose ? Et oui, InnoDB c'est un peu le ZFS de MariaDB (MyISAM étant un peu son ext4). Bref, cette étape de l'investigation représente une intersection entre deux problèmes : les exigences de MariaDB versus les exigences de ZFS. La bonne nouvelle c'est que la conclusion pourrait transformer ceci en une alliance intelligente pour un max de perf
Pour rester dans une trajectoire cohérente, j'ai continué de postuler que le problème venait d'InnoDB et j'ai donc commencé par me renseigner sur son fonctionnement. Je ne vais pas faire d'exposé ou de schéma car à vrai dire je n'ai pas eu le temps de tout comprendre, mais j'ai parcouru des ressources comme celles qui sont référencées à la fin de ce ticket et j'ai fini par trouver les paramètres décisifs :
innodb_log_file_size=64M
innodb_log_buffer_size=64M
innodb_checksum_algorithm=none
innodb_flush_neighbors=0
innodb_use_native_aio=0
innodb_use_atomic_writes=0
Pour résumer très grossièrement, ces paramètres demandent à InnoDB de se calmer sur ses écritures directes en augmentant la capacité de ses journaux d'écriture (log_file
& log_buffer_size
), et en éteignant ses features qui font doublon avec celles de ZFS (les quatre suivantes). Pour comprendre une partie de la redondance des features entre ZFS et InnoDB, la synthèse la plus simple et la plus professionnelle que j'ai trouvée est ici.
conclusion
Le lien ci avant donne également des tips pour adapter le comportement de ZFS avec InnoDB. Il sera donc bienvenu à terme d'optimiser les deux côtés sur chaque base de donnée. Bref, il est certain que l'optimisation de InnoDB a corrigé un symptôme, et il est à peu près aussi certain que combiné à une optimisation conjointe de ZFS, cela corrigera un problème de bas niveau (cf. "ZFS + SQL =
- il n'y a jamais eu besoin de cette optimisation sur talk pour que les requêtes MariaDB s'exécutent normalement auparavant
- d'autres services n'ont pas non plus besoin de cette optimisation pour fonctionner à peu près normalement depuis de longs mois (Nextcloud a des lenteurs mais reste globalement réactif)
- quand bien même le forum a connu un pic d'utilisation ces dernières semaines, cela ne peut pas expliquer la majorité du symptôme : on parle de requêtes totalement anecdotiques du genre
select * from 'flarumpost_reactions' where 'reaction_id' is not null and 'flarumpost_reactions'.'post_id' in (910, 915, 935, 1125, 1156, 1627, 1630, 1644, 1647, 2530, 2554);)
qui pouvaient attendre plus de 3 secondes avant d'avoir un résultat, quel que soit le niveau d'utilisation du serveur - le
IO delay
global du serveur, même s'il a commencé à grimper à la même période de pic d'activité du forum, ne redescend jamais, pas même la nuit, et n'est donc pas corrélé à une activité d'écriture en base de donnée d'un seul service comme talk, même si la courbe moyenne des deux sur un mois y fait penser.
Conclusion : à mon avis, résoudre ce problème a permis de montrer que la sous-optimisation d'une base de donnée rend cette dernière très vulnérable à l'état général de l'IO sur le serveur, et non seulement en cas de saturation elle s'en trouve affectée, mais en plus elle pourrait contribuer à l'empirer (même si ça ne semble pas être le cas ici).
Documentation
- https://medium.com/neoxia/deepdive-voyage-au-pays-des-lock-mysql-innodb-2bb043f9739
- https://mysql.developpez.com/tutoriels/manuel-de-reference-mysql-5-0/?page=Le-moteur-de-tables-InnoDB
- https://mariadb.com/kb/en/binary-log-group-commit-and-innodb-flushing-performance/
- https://dev.mysql.com/doc/refman/8.0/en/optimizing-innodb-transaction-management.html
- https://shatteredsilicon.net/blog/2020/06/05/mysql-mariadb-innodb-on-zfs/