dbnewz

Dans la grande majorité des applications, améliorer les requêtes qui mettent le plus de temps à s’exécuter s’avère en payant à tous les points de vue : les utilisateurs ont un meilleur ressenti de l’application grâce au gain en rapidité, la charge du serveur baisse car les requêtes lentes ont souvent pour origine un plan d’exécution coûteux et finalement le serveur est capable d’accepter plus de connexions qu’auparavant. Mais avant de pouvoir corriger ces requêtes lentes, encore faut-il les repérer afin de les analyser. C’est pourquoi je vous propose dans cet article de faire le point sur le slow query log, soit en français plus correct le journal des requêtes lentes.

Tout d’abord, il faut savoir que la version 5.1 a apporté pas mal de changements par rapport aux possibilités offertes jusqu’alors. Mais pour que les choses restent claires, nous allons commencer par présenter les options disponibles en 5.0.

Le but du journal des requêtes lentes, quelle que soit la version de MySQL, est de tracer l’ensemble des requêtes qui sont jugées lentes, c’est-à-dire dont le temps d’exécution est supérieur à une certaine limite. Ce qui est intéressant dans ce journal, c’est que le serveur écrit les requêtes après leur exécution, ce qui permet de disposer de pas mal d’informations intéressantes. Remarquez que c’est logique : on ne peut bien sûr pas savoir avant de l’avoir exécutée si une requête est lente ou pas …

L’activation/désactivation du journal se fait avec la variable log_slow_queries. Par défaut, celle-ci est à OFF :

mysql> SHOW VARIABLES LIKE 'log_slow_queries';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| log_slow_queries | OFF   |
+------------------+-------+


La variable ne peut pas être modifiée dynamiquement, le mieux est donc d’aller éditer le fichier my.cnf :

[mysqld]
log_slow_queries

puis de redémarrer le serveur.

Notez que si vous ne précisez aucun chemin, le journal est créé dans le répertoire de données (ce qui n’est pas idéal) et porte le nom hostname-slow.log. Le mieux est donc de préciser un chemin absolu, par exemple :

[mysqld]
log_slow_queries = /var/log/mysql/mysql-slow.log


La seconde option importante à configurer est la durée à partir de laquelle une requête est considérée comme lente. Ce réglage se fait avec la variable long_query_time, qui peut être modifiée dynamiquement :

mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| long_query_time | 10    |
+-----------------+-------+
1 row in set (0.00 sec)


mysql> SET @@global.long_query_time = 5;
Query OK, 0 rows affected (0.00 sec)


mysql> SHOW GLOBAL VARIABLES LIKE 'long_query_time';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| long_query_time | 5     |
+-----------------+-------+
1 row in set (0.00 sec)

Munis de ces informations, nous pouvons maintenant écrire une requête lente :

mysql> SELECT SLEEP(15);


et voir ce qui se trouve dans le journal :

# Time: 100528 11:48:13
# User@Host: msandbox[msandbox] @ localhost []
# Query_time: 15 Lock_time: 0 Rows_sent: 1 Rows_examined: 0
SELECT SLEEP(15);


Les informations des 2 premières lignes (date et utilisateur) permettent, en utilisant des outils existants ou avec son propre script, de regrouper les événements pour déterminer s’il y a plus de requêtes lentes certains jours ou à certains moments de la journée, ou encore si un utilisateur provoque plus de requêtes lentes que les autres.

La 3è ligne est particulièrement intéressante puisqu’en plus du temps d’exécution de la requête, nous avons le temps perdu à cause des verrous et nous pouvons comparer le nombre de lignes renvoyées au nombre de lignes examinées. Un examen rapide de ces informations nous permet donc rapidement de savoir si la requête est lente à cause d’une contention sur les ressources (Lock_time élevé) ou si l’exécution est loin d’être optimale (Rows_examined élevé par rapport à Rows_sent).

Un exemple réel plus parlant ? En voici un :

# Time: 100401 6:30:14
# User@Host: xxx[xxx] @ backoffice.xxx [10.xxx.xxx.xxx]
# Query_time: 12.012118 Lock_time: 0.000660 Rows_sent: 0 Rows_examined: 359462


Ici, on voit tout de suite que le plan d’exécution mériterait d’être revue : le serveur lit 360 000 lignes pour en retourner … 0 !

Du côté des limitations en 5.0, 3 points sont à noter : outre le fait de ne pas pouvoir activer/désactiver le journal sans devoir redémarrer le serveur, les requêtes exécutées sur un slave par le thread de réplication ne sont jamais tracées dans le journal et la valeur de la variable long_query_time est nécessairement un entier.

Ces deux derniers points ont des conséquences gênantes :

• si vous activez le journal sur un slave mais pas sur le master, vous risquez de passer à côté de requêtes de mises à jour qui sont lentes, les mises à jour étant toutes exécutées par le thread de réplication
• si votre application est déjà bien optimisée, votre journal sera probablement vide car vous n’aurez plus aucune requête s’exécutant en plus d’une seconde : si vous souhaitez malgré tout repérer les requêtes les plus longues à exécuter, il faudra trouver un autre moyen pour les tracer

Il existe encore 2 autres options disponibles : la possibilité de tracer les requêtes « administratives » (par exemple, REPAIR TABLE) qui sont lentes ou encore la possibilité de tracer les requêtes n’utilisant pas d’index, quel que soit leur temps d’exécution. Il suffit pour cela de renseigner l’une ou l’autre des variables dans le fichier my.cnf :


[mysqld]
log-slow-admin-statements
log-queries-not-using-indexes


L’option log-queries-not-using-indexes mérite quand même qu’on s’y attarde un peu… En effet, cette option va en réalité tracer les requêtes qui parcourent toutes les lignes d’une table, peu importe si ce parcours se fait ou non avec un index. Pas très clair ? Prenons un exemple.

Voici 2 structures de table, identiques sauf que l’une a pour moteur InnoDB et l’autre MyISAM :

CREATE TABLE t1 (
id int(11) NOT NULL auto_increment,
PRIMARY KEY (id)
) ENGINE=InnoDB



CREATE TABLE t2 (
id int(11) NOT NULL auto_increment,
PRIMARY KEY (id)
) ENGINE=MyISAM

Remplissons les tables avec quelques lignes en répétant plusieurs fois les insertions suivantes :

mysql> INSERT INTO t1 (id) VALUES (NULL);
mysql> INSERT INTO t2 (id) VALUES (NULL);


Maintenant la requête suivante va se retrouver dans le journal des requêtes lentes :

mysql> SELECT COUNT(*) FROM t1;


alors que celle-ci n’y sera pas :

mysql> SELECT COUNT(*) FROM t2;


Quelle est l’explication ? Il suffit de regarder le plan d’exécution donné par EXPLAIN. Pour la table t1, EXPLAIN indique que le plan est de faire un full index scan alors que pour t2, aucune opération n’est nécessaire (donc en particulier aucun index n’est utilisé), le moteur MyISAM gardant toujours parmi ses méta-données le nombre d’enregistrements de la table.

Dans notre cas, MySQL a donc tracé la requête utilisant un index et ignoré celle n’en utilisant pas… Quand je disais que cette option méritait qu’on s’y attarde un peu !

Maintenant que nous avons fait le tour de ce qui est possible en 5.0, voyons ce que la 5.1 a apporté de neuf. C’est simple : que du bon ! Ainsi, il est désormais possible d’activer/désactiver le journal dynamiquement, de tracer les requêtes lentes dans un fichier ou dans une table, d’indiquer un seuil non plus en secondes mais en microsecondes et enfin de tracer les requêtes exécutées par le thread de réplication !

Dans le détail, c’est un peu plus compliqué…

La variable log_slow_queries a été remplacée par slow_query_log : c’est grâce à elle que vous activez/désactivez le journal.

Par défaut, le journal est écrit dans un fichier, dont vous pouvez préciser le nom avec la variable slow_query_log_file.

Pour écrire dans une table, il faut modifier la variable log_output en précisant TABLE. Vous pouvez aussi choisir d’écrire à la fois dans un fichier et dans une table avec log_output = FILE, TABLE. Attention, la variable log_output s’applique également au journal général (general log) si celui-ci est activé.

Le seuil décrit par long_query_time s’écrit toujours en secondes, mais avec une précision pouvant aller jusqu’à la microseconde. Vous pouvez donc maintenant définir un seuil de 0.05s : long_query_time = 0.05. Attention, si vous écrivez dans une table, la granularité redevient la seconde comme en 5.0 !

Une petite nouveauté aussi, vous avez la possibilité de ne tracer que les requêtes qui examinent au moins un certain nombre de lignes avec la variables min_examined_row_limit.

Enfin, dernier point, la variable log-slow-slave-statements, disponible à partir de la 5.1.45 permet de tracer les requêtes lentes exécutées par le thread de réplication.

Ca y est, vous savez tout sur le journal des requêtes lentes de MySQL ! Enfin, presque, car si vous utilisez la version de MySQL patchée par Percona, vous trouverez des informations supplémentaires. Ceci fera sans doute l’objet d’un nouvel article. En attendant, nous examinerons prochainement quels sont les outils disponibles pour analyser les requêtes lentes.

Cet article a été publié le Vendredi 28 mai 2010 à 4:36 et est classé dans MySQL. Vous pouvez en suivre les commentaires par le biais du flux RSS 2.0. Vous pouvez laisser un commentaire, ou faire un trackback depuis votre propre site.