Dans cet article, je vais vous raconter une petite histoire de diagnostic comme il nous - ingénieurs, développeurs et autres artisans du code - en arrive très souvent.
C’est une histoire technique qui parle de base de données, de logs, d’ORM sûrement mal configuré et de MySQL qui fait ce qu’on lui dit. C’est surtout l’histoire de comment et pourquoi on a regardé au mauvais endroit en apprenant pleins de trucs au passage.
L’histoire commence avec un problème : l’équipe observe parfois des ralentissements dans notre application. Quelques logs plus tards, on suspecte sérieusement la base de données d’en être l’origine.
Afin de s’en assurer, on a dû répondre aux questions suivantes :
La réponse à la première question dépend de notre métier, du volume de données traité ainsi que de la nature des traitements effectués.
On peut cependant répondre à la seconde question de différentes manières : logs proxy, applicatifs, base de données, relevés manuels, etc.
Dans notre cas, nous avons mis en oeuvre les slow logs, côté base de données donc. Ces derniers permettent de définir une durée seuil à partir de laquelle MySQL considérera que la requête a pris trop de temps. Si tel est le cas, MySQL inscrit dans un fichier ou une table (selon votre configuration) la requête incriminée ainsi que différentes informations associées.
Dans notre contexte, nous avons défini ce seuil à 100ms.
Cette ligne de log ressemble à ça :
Afin d'activer les slow logs, il convient d'appliquer la configuration qui va bien :
Quelques explications :
Pour information, vous pouvez consulter l'état de votre configuration via la requête suivante :
Plus d'informations sur les logs MySQL peuvent être trouvées dans la documentation officielle.
Il ne reste plus qu'à observer le fichier de log en attendant qu'il se remplisse :
@@ARTICLE_CONTENT@@gt; tail -f /var/log/mysql/slow-query.log
On est maintenant équipé pour la traque aux requêtes lentes !
La requête incriminée concerne une table ressemblant fortement au schéma suivant :
Cette table contient les données suivantes :
Lors de l'exploitation de notre table aux 1 million de lignes, le slow query log nous remonte la ligne suivante :
Et c'est là que le bât blesse : un select qui prends 0,65s alors que la requête contient une clause where sur une colonne indexée. "What the fuck" comme dirait l'autre.
Afin de comprendre ce qu'il se passe, MySQL fournit une commande permettant de détailler le comportement d'une requête SQL. Il suffit d'exécuter la requête posant problème en la préfixant avec l'instruction EXPLAIN.
Avec notre requête, on obtient ça :
Si vous n’avez jamais utilisé EXPLAIN, ces informations peuvent paraître bien absconses. C’est en tout cas ce que notre équipe a pensé sur le moment. La documentation MySQL est cependant bien faite. Voici la signification des différentes colonnes :
Parmi toutes ces colonnes, 2 nous intéressent particulièrement : "type" et "possible_keys".
La valeur "ALL" de la colonne "type" nous indique de MySQL a effectué un "full scan", c'est-à-dire qu'il a parcouru toute la table à la recherche de la ligne dont l'id est 150000. Sans utiliser d'index alors que celui-ci existe, comme l'indique la colonne "possible_keys".
On va quand même s'assurer de l'existence de cet index, au cas-où :
La colonne "Key_name" nous indique qu'un index est bien présent sur la clé primaire de la table.
Si on résume les éléments du problème, on voit que :
Bon, tout semble en ordre, alors quoi ?
Rien n'est évident pour nous à ce instant-là, c'est donc le moment d'essayer des choses afin de diminuer notre WTFomètre.
Plutôt que de résoudre immédiatement notre problème, on a choisi de désactiver le cache MySQL afin de voir si les temps de réponse étaient modifiés. Il ne s'agirait pas de croire avoir trouvé la solution alors que c'est le cache qui s'est mis à nous répondre…
C’est là qu’intervient le flag SQL_NO_CACHE :
Réponse en 0,80s, donc rien de concluant ce côté là. Néant aussi côté EXPLAIN. On va tout de même conserver le flag SQL_NO_CACHE dans nos futures requêtes afin d'éliminer la possibilité que ce dernier intervienne.
L'optimiseur de requêtes MySQL s'appuie sur des statistiques qu'il constitue lui-même afin de déterminer quel index est le plus pertinent.
L'équipe s'est donc dit que, en raison d'une forte sollicitation de la table, les statistiques d'usage de la table étaient devenues incorrectes. Notre index serait donc considéré comme non-pertinent par MySQL. La commande ANALYZE permet de recalculer ces statistiques.
Essayons ça…
Super ! Maintenant la requête :
Aaaaaaand... Nop.
La commande OPTIMIZE permet (entre autres) de reconstruire la table. Cela va provoquer au passage l'exécution d'un ANALYZE. Et cela va aussi libérer l'espace libre inutilisé.
En gros, une bonne douche froide afin de remettre de l'ordre dans les idées de MySQL. Cette commande est intéressante notamment quand MySQL subit une forte charge en écriture et suppression et où le désordre règne.
Avec un peu de chance, le combo réorganisation des données + mise à jour des statistiques d'usage de l'index fera le job !
Attention, cette requête peut prendre un certain temps. Je suggère de se référer à la documentation officielle pour en étudier la pertinence.
Essayons de requêter la base de nouveau :
Bon, bon, bon... Toujours pas.
Forcer l'index nous permet d'indiquer à MySQL l'index à utiliser dans la requête. Cela peut aider quand MySQL n'identifie pas automatiquement l'index le plus approprié (quand les statistiques évoquées dans la section au-dessus sont incorrectes par exemple):
Plus d'information sur USE INDEX dans la documentation officielle.
Bon... La requête a duré 0,65s, je vous épargne le EXPLAIN qui nous dit que MySQL a effectué un full scan :(
Ignorer l'index permet de voir ce qui se passe... sans l'index. Histoire d'être vraiment sûr. Non, parce que là, on sait plus trop.
Et le EXPLAIN nous dit bien qu'il n'a utilisé aucun index :
Comme toujours quand on a exploré toutes les pistes, il faut savoir regarder à l’extérieur de la boî-boîte..
Dans la réalité, notre requête est générée par notre ORM, JPA en l'occurrence. Or en comparant la classe JPA "Article" et le schéma de la table "articles", on a vu ceci :
Côté Java :
Côté SQL :
Vous voyez ? Non, pas encore ?
Le type utilisé pour "article_id" côté Java est un Integer alors qu'on a un VARCHAR côté SQL. C'est la raison pour laquelle la requête générée par l'ORM est la suivante :
Notez l'absence de guillemets autour de 150000. Attendez, cela voudrait-il dire qu’avec des guillemets...
0.00s !! Et le EXPLAIN qui va bien :
Hourra, MySQL utilise enfin notre index !
Pour la correction, deux choix : changer le type de l’attribut “article_id” côté base ou côté Java. Dans notre contexte, il était plus pertinent et moins coûteux de changer le type côté Java (en String plutôt qu'en Integer donc).
Pour la petite explication, il se trouve que MySQL va exécuter la requête mais ignorera l'index quand le type utilisé dans la clause where est incorrect. La colonne est un VARCHAR, le type Java est un Integer, ce qui se traduit par une absence de guillemets dans la requête. Voilà.
A noter que l’inverse est faux : si votre type côté base de données est un entier, alors utiliser un type string dans la clause where de la requête sollicitera quand même l'index. ¯\_(ツ)_/¯
Comment aurait-on pu faire différemment ? Mieux ?
J’ai donc appris depuis qu’il existe un flag de configuration Hibernate permettant de valider que les types des schémas base de données correspondent à ceux des entités Java. Il s’appelle “hbm2ddl2.auto” et prend la valeur “validate” (plus d’info ici). C’est un début.
On aurait aussi pu générer les entités Java depuis le schéma des bases de données. On avait choisi à l’époque de les écrire à la main sans imaginer que cela nous mène dans ce genre d’impasse. Si j’avais à refaire les choses, je générerais plutôt ces classes automatiquement, idéalement lors de l’écriture des scripts de migration base de données.
Il reste que cet échec silencieux de MySQL en mode “je sais qu’il y a un index mais je ne l’utilise pas, je ne te dis rien sauf si tu configures explicitement ton MySQL pour l’identifier et si ton volume de données explose, ta performance sera flinguée”, ne me satisfait pas vraiment. La permissivité de MySQL quant au non-fail d’une requête dont le comparant utilisé dans la clause where ne respecte le type de la colonne comparée est un poil décevante. Le flag “log_queries_not_using_indexes”, évoqué en début d’article, est un début de réponse (à ce problème spécifique seulement) mais requiert quelques étapes manuelles pour fonctionner.
Dans cet article, on a vu comment :
Plus généralement, on a appris pleins de trucs. Et ça c'est bien.