Outils d’analyse de requêtes lentes – mysqldumpslow

8 juillet 2010 par stephane

Nous avons vu dans un précédent article comment tracer les requêtes lentes avec MySQL et quelles sont les possibilités selon la version du serveur. Si vous avez activé le journal des requêtes lentes, vous avez sans doute recueilli un certain nombre de requêtes qu’il faut maintenant analyser afin de pouvoir les optimiser ou afin de revoir le paramétrage du serveur. Cet article est le premier d’une série de trois, qui va vous montrer quelques outils qui vont vous aider dans cette analyse.

Avant toute chose, montons une petite configuration qui va nous être utile pour illustrer le fonctionnement et les limitations de chaque outil.

Prenons un serveur MySQL en version 5.1 avec la table exemple sakila et choisissons une valeur de long_query_time de 0.05s. Pourquoi une valeur aussi faible ? Tout simplement parce qu’avec une telle valeur, il n’est vraiment pas difficile des requêtes qui seront considérées comme lentes, ce qui nous permettra d’obtenir facilement un journal de requêtes lentes.

Effectuons les requêtes suivantes :

(1) mysql> SELECT customer_id,COUNT(*) FROM rental WHERE return_date > '2005-01-01' GROUP BY customer_id;
(2) mysql> SELECT customer_id,COUNT(*) FROM rental WHERE return_date > '2005-01-02' GROUP BY customer_id;
(3) mysql> SELECT customer_id,COUNT(*) FROM rental WHERE return_date > '2005-01-03' GROUP BY customer_id;
(4) mysql> CREATE TABLE rental2 LIKE rental;
(5) mysql> INSERT INTO rental2 SELECT * FROM rental;

Toutes les requêtes, sauf (4), sont lentes (si ce n’est pas le cas pour vous, il vous suffit de baisser la valeur de long_query_time).

Le journal des requêtes lentes a maintenant l’allure suivante :

# Time: 100707 14:11:51
# User@Host: msandbox[msandbox] @ localhost []
# Query_time: 0.074232 Lock_time: 0.000061 Rows_sent: 599 Rows_examined: 16044
use sakila;
SET timestamp=1278504711;
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-01' GROUP BY customer_id;
# Time: 100707 14:12:10
# User@Host: msandbox[msandbox] @ localhost []
# Query_time: 0.052575 Lock_time: 0.000117 Rows_sent: 599 Rows_examined: 16044
SET timestamp=1278504730;
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-02' GROUP BY customer_id;
# Time: 100707 14:12:15
# User@Host: msandbox[msandbox] @ localhost []
# Query_time: 0.059561 Lock_time: 0.000060 Rows_sent: 599 Rows_examined: 16044
SET timestamp=1278504735;
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-03' GROUP BY customer_id;
# Time: 100707 14:12:42
# User@Host: msandbox[msandbox] @ localhost []
# Query_time: 0.718344 Lock_time: 0.000259 Rows_sent: 0 Rows_examined: 16044
SET timestamp=1278504762;
INSERT INTO rental2 SELECT * FROM rental;

Plutôt que de montrer toutes les possibilités des outils que nous allons regarder, je vous propose de nous concentrer sur quelques questions clés que l’on se pose souvent et de voir si les outils examinés permettent de répondre à ces questions :

- Comment ne garder que les groupes de requêtes qui ont entraîné le plus long temps de réponse ?
- Comment ne garder que les groupes de requêtes qui ont le plus d’occurences ?
- Comment ne garder que les requêtes qui prennent plus de x secondes ?
- Comment ne garder que les SELECT ?

La deux premières questions demandent quelques éclaircissements : qu’est-ce qu’un groupe de requêtes et pourquoi une même requête, pas trop lente mais s’exécutant plusieurs fois, serait-elle plus intéressante à analyser qu’une requête très lente ?

Premièrement, il suffit de regarder les 4 premières requêtes du listing ci-dessus pour s’apercevoir que les requêtes sont identiques à une constante près. Un appel à EXPLAIN donnera le même résultat pour toutes les requêtes, et l’amélioration de l’une d’elles les améliorera toutes.
Et deuxièmement, il faut garder à l’esprit qu’une requête exécutée 1000 fois par seconde en 1 ms chargera plus le serveur qu’une requête exécuté 1 fois par seconde en 0.5s. La recherche des requêtes qui provoquent le plus de charge est un travail aussi important que la recherche des requêtes les plus lentes.

Nous allons regarder dans cet article mysqldumpslow, qui est un script Perl que vous trouverez dans toute distribution MySQL. Ce script est assez rustique (il a été écrit en 2000 !) mais comme c’est le seul outil d’analyse fourni en standard, nous allons y jeter un oeil.

L’utilisation est très simple : il suffit de passer le chemin du journal au script, avec éventuellement des options que nous allons examiner un peu plus loin.

Voici ce que nous obtenons dans notre cas :

$ mysqldumpslow msandbox-slow.log


Reading mysql slow query log from msandbox-slow.log
Count: 1 Time=0.72s (0s) Lock=0.00s (0s) Rows=0.0 (0), msandbox[msandbox]@localhost
insert into rental2 select * from rental

Count: 3 Time=0.06s (0s) Lock=0.00s (0s) Rows=599.0 (1797), msandbox[msandbox]@localhost
select customer_id,count(*) from rental where return_date>'S' group by customer_id

Quelques commentaires sur le rapport obtenu :

- Les requêtes sont rassemblées au sein de groupes comme nous l’avons expliqué. Les constantes qui changent entre chaque requête d’un même groupe sont remplacées par un S, ce qui indique que les valeurs réelles sont des chaines de caractères ou par un N, ce qui indique que les valeurs réelles sont des nombres. Cette présentation concise est bien pratique car très souvent vous retrouverez le même type de requêtes exécuté des dizaines ou des centaines de fois, mais elle a pour inconvénient de ne pas fournir de requête directement exploitable : si vous voulez utiliser EXPLAIN, il vous faudra d’abord remplacer le S par une ‘vraie’ valeur, ce qui peut s’avérer désagréable à l’usage. Il est possible de demander à mysqldumpslow de ne pas rendre abstraites les constantes, mais dans ce cas, chaque requête d’un groupe est considérée comme unique si bien que le regroupement est perdu.

- Les champs Time, Lock et Rows reprennent les informations du journal, en mentionnant la valeur moyenne et la valeur totale (entre parenthèses) de chaque champ pour le groupe. Notez que pour les valeurs totales de Time et Lock, l’unité est la seconde, ce qui était bien adapté en 2000 quand la résolution du journal était la seconde, mais ne l’est plus du tout dans notre cas. Ces valeurs ne sont donc pas toujours exploitables.

Pouvons-nous répondre aux questions que nous nous étions posées avec mysqldumpslow ?

Pour les 2 premières (groupe de requêtes ayant le plus d’occurences et ayant entrainé le plus long temps de réponse), la réponse est oui. mysqldumpslow dispose en effet d’une option pour trier les entrées du rapport selon différents critères. Ainsi :
mysqldumpslow -s c msandbox-slow.log
trie les groupes de requêtes par nombre d’occurences. Et

mysqldumpslow -s t msandbox-slow.log
trie les groupes de requêtes par temps d’exécution. Notez que le tri se fait sur le temps total, ie le chiffre entre parenthèses. Si vous préférez que le tri se fasse sur le temps moyen il faut utiliser l’option -s at.

Pour la troisième question, portant sur les requêtes prenant plus de x secondes, nous ne pouvons pas directement obtenir le résultat. Mais nous pouvons nous en approcher en triant par temps de réponse et en utilisant l’option -t qui n’affiche que les N premiers résultats :
mysqldumpslow -s t -t 1 msandbox-slow.log
donne le groupe de requêtes ayant le temps total d’exécution le plus long. Il suffit alors de trouver, par tâtonnements successifs par exemple, la bonne valeur de l’option -t qui va nous permettre d’obtenir le résultat voulu.

Quant à la dernière question, à savoir filtrer l’affichage sur les SELECT, il existe bien une option -g qui permet de fournir un motif de filtrage, mais il ne m’a pas semblé possible dans notre cas de trouver un motif qui filtre le INSERT … SELECT sans filtrer les SELECT.

Résumons donc : mysqldumpslow est un outil très simple, toujours disponible, qui permet de produire un rapport concis mais peu précis en regroupant les requêtes similaires. Les possibilités de filtrage sont réduites au minimum, ce qui n’en fait pas un outil très pratique quand le journal contient beaucoup d’entrées. On l’utilisera donc surtout quand aucun autre outil n’est disponible, ce qui devrait être finalement assez rare, puisque rien ne vous empêche de rapatrier le journal de requêtes lentes sur votre PC pour l’analyser avec un autre outil.

Rendez-vous très bientôt pour la seconde partie de notre découverte des outils d’analyse de journaux de requêtes lentes avec mysqlsla.

Mots-clefs : ,

2 commentaires sur “Outils d’analyse de requêtes lentes – mysqldumpslow”

  1. [...] dbnewz le blog français sur les SGBD – MySQL, Oracle et plus… « Outils d’analyse de requêtes lentes – mysqldumpslow [...]

  2. [...] aux 4 questions que nous nous étions posées lors de l’article précédent, qui vont nous permettre de voir comment utiliser les méta-données des requêtes pour trier ou [...]

Laisser une réponse