Il était une fois… une - presque - histoire d’index
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.
Mettre un doigt sur le problème
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 :
- Quels sont les temps de réponses attendus ?
- Quelles métriques peuvent être mises en oeuvre pour mesurer ces temps de réponse ?
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 :
- "log_output" indique que les logs doivent être écrits dans le filesystem
- "log_queries_not_using_indexes" indique que MySQL inclura dans ce log les requêtes n'utilisant pas d'index
- "long_query_time" indique la durée seuil (en secondes) à partir de laquelle MySQL loggera la requête. Le seuil est ici défini à 100ms.
- "slow_query_log" active les slow logs
- "slow_query_log_file" indique le fichier dans lequel logger les requêtes
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 !
Les données du problème
La requête incriminée concerne une table ressemblant fortement au schéma suivant :
Cette table contient les données suivantes :
Une certaine lenteur se fait sentir
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.
Place au diagnostic !
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 :
- "id" indique l'identifiant de la commande SELECT
- "select_type" indique la nature/type du SELECT, il peut prendre les valeurs SIMPLE, PRIMARY, UNION, etc.
- "table" contient le nom de la table concernée par la sortie de la requête
- "partitions" indique les partitions mise en oeuvre, NULL est utilisé quand la table n'est pas partitionnée
- "type" indique la nature de la jointure
- "possible_keys" indique les index que MySQL peut utiliser
- "key" indique l'index que MySQL a utilisé
- "key_len" indique la longueur de la clé que MySQL à utiliser
- "ref" indique la colonne utilisée afin d'effectuer la comparaison avec l'index
- "rows" indique le nombre de lignes que MySQL croit devoir examiner pour exécuter la requête
- "filtered" indique l'estimation (en %) des lignes de la table qui seront filtrée à lors de l'exécution de la requête
- "extra" ajoute des informations complémentaires à l'exécution de la requête par MySQL
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 :
- La table contient une clé primaire sur la colonne "article_id"
- La colonne "article_id" est de type VARCHAR
- Il existe un index associé à la colonne "article_id"
- La requête contient une clause where sur la colonne indexée
- L'index n'est pas utilisé
Bon, tout semble en ordre, alors quoi ?
Le temps des hypothèses
Rien n'est évident pour nous à ce instant-là, c'est donc le moment d'essayer des choses afin de diminuer notre WTFomètre.
Essai n°1 : désactiver le cache MySQL
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.
Essai n°2 : recalculer les statistiques liées aux index de la table
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.
Essai n°3 : optimiser la table
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.
Essai n°4 : on force l'index
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 :(
Essai n°5 : et en ignorant l'index peut-être ?
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 :
Alors cette solution ?
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. ¯\_(ツ)_/¯
Apprendre de ses leçons
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.
Bilan
Dans cet article, on a vu comment :
- définir un seuil de durée à partir duquel considérer qu'une requête prend trop de temps (avec les slow logs)
- comprendre le plan d'exécution d'une requête MySQL (avec EXPLAIN)
- afficher les index associés à une table (avec SHOW INDEX)
- désactiver le cache MySQL (avec SQL_NO_CACHE)
- recalculer les statistiques liées aux index d'une table (avec ANALYZE)
- recalculer les statistiques liées aux index d'une table et réorganiser le positionnement sur le disque d'une table (avec OPTIMIZE)
- forcer l'utilisation d'un index (avec USE INDEX)
- empêcher l'utilisation d'un index (avec IGNORE INDEX)
Plus généralement, on a appris pleins de trucs. Et ça c'est bien.