Outils d’analyse de requêtes lentes – mk-query-digest

22 septembre 2010 par stephane

Et voici notre troisième et dernière partie consacrée aux outils d’analyse de requêtes lentes. Aujourd’hui, après le très simple mysqldumpslow et le configurable mysqlsla, nous allons examiner mk-query-digest, un des scripts Perl faisant partie de la suite Maatkit.

mk-query-digest permet d’analyser de nombreux types de journaux et présente un rapport qu’on peut configurer de multiples manières. Contrairement à mysqlsla qui ne sait lire que des fichiers journaux, mk-query-digest offre la possibilité d’analyser d’autres sources de requêtes, par exemple des paquets issus de tcpdump. Un autre point fort de cet outil est le nombre d’options disponibles, qui permettent de filtrer ou classer les entrées analysées de manière à obtenir exactement le rapport que chacun souhaite.

Comme toujours, notre propos va commencer par l’installation de l’outil. Pour cela, il existe 2 possibilités.
Si vous souhaitez utiliser seulement mk-query-digest, vous pouvez télécharger la dernière version stable du script ici. Ensuite il ne vous reste plus qu’à le rendre exécutable :

# chmod u+x mk-query-digest

Si vous préférez installer tous les scripts de Maatkit, vous pouvez télécharger la dernière archive sur cette page. Après avoir extrait l’archive, les classiques

$ perl Makefile.PL
$ make
# make install

installeront les scripts ainsi que les pages de man associées.

Rappelons maintenant les points que nous avions examinés avec les autres outils :

  • 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 ?

Commençons par lancer mk-query-digest sans option particulière (la sortie a été légèrement modifiée pour des raisons de lisibilité) :

$ mk-query-digest msandbox-slow.log


# 60ms user time, 440ms system time, 11.22M rss, 14.34M vsz
# Current date: Tue Sep 21 16:10:19 2010
# Files: slow.txt
# Overall: 4 total, 2 unique, 0.08 QPS, 0.02x concurrency
#           total     min     max     avg     95%
# Exec time 905ms    53ms   718ms   226ms   705ms
# Lock time 497us    60us   259us   124us   247us
# Rows sent 1.75k       0     599  449.25  592.07
# Rows exam 62.67k 15.67k  15.67k  15.67k  15.67k
# Time range 2010-07-07 14:11:51 to 2010-07-07 14:12:42
# bytes 313 40 91 78.25 88.31 21.55 88.31


# Profile
# Rank    Query ID     Resp. time  Calls R/Call   Item
# ====   =========    ===========  ===== ====== ========
#    1   0xCD0CD89     0.7183 79.4%  1  0.7183  INSERT
#    2   0x602DDF4     0.1864 20.6%  3  0.0621  SELECT


# Query 1: 0 QPS, 0x concurrency, ID 0xCD0CD89 at byte 820 ______
# This item is included in the report because it matches --limit.
# pct total min max avg 95% stddev median
# Count 25 1
# Exec time 79 718ms 718ms 718ms 718ms 718ms 0 718ms
# Lock time 52 259us 259us 259us 259us 259us 0 259us
# Rows sent 0 0 0 0 0 0 0 0
# Rows exam 25 15.67k 15.67k 15.67k 15.67k 15.67k 0 15.67k
# Users 1 msandbox
# Hosts 1 localhost
# Databases 1 sakila
# Time range 2010-07-07 14:12:42 to 2010-07-07 14:12:42
# bytes 12 40 40 40 40 40 0 40
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms ################################################
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `sakila` LIKE 'rental2'\G
# SHOW CREATE TABLE `sakila`.`rental2`\G
# SHOW TABLE STATUS FROM `sakila` LIKE 'rental'\G
# SHOW CREATE TABLE `sakila`.`rental`\G
INSERT INTO rental2 SELECT * FROM rental\G


# Query 2: 0.12 QPS, 0.01x concurrency, ID 0x602DDF4 at byte 0 __
# This item is included in the report because it matches --limit.
# pct total min max avg 95% stddev median
# Count 75 3
# Exec time 20 186ms 53ms 74ms 62ms 71ms 8ms 59ms
# Lock time 47 238us 60us 117us 79us 113us 25us 60us
# Rows sent 100 1.75k 599 599 599 599 0 599
# Rows exam 75 47.00k 15.67k 15.67k 15.67k 15.67k 0 15.67k
# Users 1 msandbox
# Hosts 1 localhost
# Databases 1 sakila
# Time range 2010-07-07 14:11:51 to 2010-07-07 14:12:15
# bytes 87 273 91 91 91 91 0 91
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms ################################################
# 100ms
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `sakila` LIKE 'rental'\G
# SHOW CREATE TABLE `sakila`.`rental`\G
# EXPLAIN
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-01' GROUP BY customer_id\G

Le rapport fourni est complet et complexe ! Examinons-le en détail.

Il débute par un résumé présentant pour différents critères (temps d’exécution, nombre de lignes examinées, etc) le total, la moyenne, le minimum, le maximum et quelques autres informations statistiques. Le rapport étant configurable, il existe des options pour trier selon n’importe lequel de ces critères. On voit également que l’outil a bien regroupé tout seul les requêtes similaires (Overall: 4 total, 2 unique).

Ensuite un petit tableau dresse un portrait rapide des requêtes analysées, en leur donnant un identifiant, qui peut par exemple permettre de naviguer rapidement dans le rapport, et en donnant leur contribution relative sur l’ensemble des requêtes lentes. Ce tableau montre que par défaut, l’outil regroupe les requêtes similaires et place en premier les requêtes qui ont causé le plus long temps d’exécution : nous avons donc la réponse à notre première question.

Puis vient une section qui sera répétée pour chaque requête analysée. On y retrouve les informations présentées dans le résumé du début du rapport, ainsi qu’une représentation de la distribution des temps d’exécution de la requête, puis les requêtes classiques à lancer pour avoir plus d’informations sur les tables impliquées dans la requête et le plan d’exécution (SHOW TABLE STATUS, SHOW CREATE TABLE, EXPLAIN). De ce point de vue, le rapport est très complet et très simple à exploiter avec un peu d’habitude : d’un seul coup d’oeil, on dispose en effet de toutes les informations nécessaires pour connaître le comportement de la requête.

Maintenant que le format du rapport fourni par mk-query-digest est devenu plus clair, voyons quelles options nous pouvons appeler pour répondre aux différentes questions que nous nous étions posées.

Pour répondre à notre deuxième question, il nous faut changer l’ordre suivant lequel les requêtes sont triées. L’option --order-by permet justement de spécifier cet ordre : elle prend un double argument, en premier le critère selon lequel trier et en second la fonction d’agrégation à appliquer sur le critère (total avec sum, nombre d’occurrences avec cnt, minimum avec min et maximum avec max). Par défaut, cette option vaut "Query_time:sum", ce qui signifie que les requêtes sont triées sur le total de leur temps d’exécution. Ici nous souhaitons connaître les requêtes ayant le plus d’occurrences, la fonction d’agrégation sera donc cnt. Dans ce cas, le critère choisi n’a pas d’importance, nous pouvons donc lancer la commande suivante :

$ mk-query-digest --order-by "Query_time:cnt" msandbox-slow.log

Pour plus de clarté, je ne reproduis pas le rapport. Sachez seulement que cette commande ne donne pas tout à fait le résultat escompté, comme le montre le tableau récapitulatif des requêtes analysées :

# Profile
# Rank  Query ID   Resp. time Calls R/Call Item
# ==== ========= ============ ===== ====== =============
# 1    0x602DDF4 0.1864 100.0%    3 0.0621 SELECT rental

Il faut jouer sur l’option --limit, par exemple de cette manière :

$ mk-query-digest --order-by "Query_time:cnt" --limit 5 msandbox-slow.log

Passons à notre troisième question : les requêtes ayant un temps d’exécution supérieur à x secondes. Cette fois, aucune option ne permet d’aboutir directement au résultat. Mais mk-query-digest, tout comme mysqlsla, permet d’écrire des filtres avec --filter. Cette option prend en paramètre des directives Perl, ce qui autorise à peu près tout type de filtre possible et imaginable.

Chaque requête avec son lot d’informations trouvées dans le journal ou calculées par mk-query-digest est représentée par l’objet $event. Dans notre cas, il nous suffit de savoir que le temps d’exécution est stocké dans l’attribut Query_time (sauf exception, les attributs ont un nom logique par rapport à ce qu’ils représentent) pour écrire la bonne commande, en supposant que le x qui nous intéresse vaut 0.1 :

$ mk-query-digest --filter '$event->{Query_time} > 0.1'

Ce principe de filtre va nous aider à répondre à la dernière question : comment ne conserver que les SELECT ? Seul problème : quel est l’attribut de $event qui contient le texte de la requête ? Plutôt que de parcourir le code du script, nous pouvons demander à mk-query-digest d’afficher la liste des attributs disponibles :

$ mk-query-digest --filter 'print Dumper($event)' msandbox-slow.log

Et avant le rapport, l’outil affiche la sortie suivante :

$VAR1 = {
  Lock_time => '0.000061',
  Query_time => '0.074232',
  Rows_examined => '16044',
  Rows_sent => '599',
  arg => 'SELECT customer_id,COUNT(*) FROM rental WHERE return_date>\'2005-01-01\' GROUP BY customer_id',
  bytes => 91,
  cmd => 'Query',
  db => 'sakila',
  fingerprint => 'select customer_id,count(*) from rental where return_date>? group by customer_id',
  host => 'localhost',
  ip => '',
  pos_in_log => '0',
  timestamp => '1278504711',
  ts => '100707 14:11:51',
  user => 'msandbox'
};

Comme nous voulons savoir si une requête est un SELECT ou non, nous pouvons utiliser au choix l’attribut arg ou l’attribut fingerprint. Il faut simplement se rappeler que arg contient le texte original de la requête et qu’il faudra faire une recherche insensible à la casse alors que fingerprint contient une version abstraite de la requête pour laquelle tout le texte est en minuscules. Voici les deux versions de la commande :

$ mk-query-digest --filter '$event->{arg} =~ m/select/i' msandbox-slow.log


$ mk-query-digest --filter '$event->{fingerprint} =~ m/select/' msandbox-slow.log

Remarquez la recherche écrite sous forme d’une regexp Perl et le i magique dans la première commande qui lance une recherche insensible à la casse.

Ainsi, mk-query-digest, tout comme mysqlsla, est suffisamment configurable pour répondre aux questions que nous nous étions posées. Lequel des deux outils vaut-il mieux choisir ? Bien souvent, ce sera une affaire de goût : les deux scripts sont capables de répondre à la plupart des cas de figure que l'on rencontre fréquemment. Parmi les différences significatives qui pourront guider votre choix, sachez que mk-query-digest dispose de plus d'options et donc de possibilités, mais que son utilisation est en conséquence un peu moins intuitive. Enfin, comme nous l'avions signalé, mysqlsla n'est plus maintenu alors que mk-query-digest est en plein développement et donc en constante amélioration.

Mots-clefs : , , ,

Un commentaire sur “Outils d’analyse de requêtes lentes – mk-query-digest”

  1. [...] requêtes lentes mais son exploitation reste difficile sans un outil adapté. Le blog dbnewz montre comment utiliser mk-query-digest, l'un des nombreux outils de Maatkit, que je vous recommande chaudement soit dit en [...]

Laisser une réponse