Outils d’analyse de requêtes lentes – mysqlsla

28 juillet 2010 par stephane

Pour ce second volet de notre série consacrée aux outils d’analyse de requêtes lentes, nous allons nous pencher aujourd’hui sur mysqlsla, qui est un script Perl disposant de nombreuses options d’agrégation et de filtrage.

Commençons par l’installation du script. Rien de plus simple, il vous suffit pour commencer de télécharger et de décompresser une archive de l’outil, disponible ici. Ensuite, des classiques

$ perl Makefile.PL
$ make
# make install

vous permettent d’installer le script. Notez, point agréable, qu’une page de man est intégrée. Si vous cherchez la syntaxe d’une option, un man mysqlsla vous dispensera donc bien souvent d’aller faire un tour sur le site du projet.

mysqlsla est plus généraliste que mysqldumpslow dans le sens où il est capable de traiter tout type de journal (requêtes lentes, mais aussi journal binaire ou journal général, ou encore journal défini par l’utilisateur). Les principes que nous allons voir dans cet article pour les requêtes lentes sont aussi valables pour les autres types de journaux.

L’idée de base de mysqlsla est de pouvoir analyser des fichiers journaux en leur appliquant éventuellement des filtres afin de ne garder que certains événements et d’émettre un rapport personnalisable présentant les résultats de cette analyse. Dans cet article nous allons seulement regarder les capacités de filtrage de mysqlsla et pas la manière de produire un rapport personnalisé, puisque le rapport par défaut nous convient très bien.

Pour un premier essai, lançons mysqlsla sans paramètre particulier à part l’option lt (comme log type) qui indique au script que le fichier passé est un journal de requêtes lentes. Cette option n’est en réalité pas indispensable car mysqlsla sait détecter automatiquement le type de journal :

$ mysqlsla -lt slow msandbox-slow.log
Report for slow logs: msandbox-slow.log
4 queries total, 2 unique
Sorted by 't_sum'
Grand Totals: Time 1 s, Lock 0 s, Rows sent 1.80k, Rows Examined 64.18k

________________________________________________ 001 ___
Count : 1 (25.00%)
Time : 718.344 ms total, 718.344 ms avg, 718.344 ms to 718.344 ms max (79.40%)
Lock Time (s) : 259 s total, 259 s avg, 259 s to 259 s max (52.11%)
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 16.04k avg, 16.04k to 16.04k max (25.00%)
Database : sakila
Users :
msandbox@localhost : 100.00% (1) of query, 100.00% (4) of all users

Query abstract:
SET timestamp=N; INSERT INTO rental2 SELECT * FROM rental;

Query sample:
SET timestamp=1278504762;
INSERT INTO rental2 SELECT * FROM rental;

________________________________________________ 002 ___
Count : 3 (75.00%)
Time : 186.368 ms total, 62.123 ms avg, 52.575 ms to 74.232 ms max (20.60%)
Lock Time (s) : 238 s total, 79 s avg, 60 s to 117 s max (47.89%)
Rows sent : 599 avg, 599 to 599 max (100.00%)
Rows examined : 16.04k avg, 16.04k to 16.04k max (75.00%)
Database : sakila
Users :
msandbox@localhost : 100.00% (3) of query, 100.00% (4) of all users

Query abstract:
SET timestamp=N; SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'S' GROUP BY customer_id;

Query sample:
SET timestamp=1278504711;
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-01' GROUP BY customer_id;

A première vue, ce rapport ressemble à celui de mysqldumpslow avec un regroupement des requêtes similaires. Le rapport est cependant plus complet car pour chaque groupe, nous avons les valeurs minimales, moyennes et maximales ainsi qu’une information très intéressante sur le poids relatif de chaque groupe, ce qui permet de cibler facilement les requêtes qui ont le plus contribué au temps de réponse ou qui ont examiné le plus de lignes.

Autre point à noter : pour chaque groupe de requêtes, mysqlsla nous présente une vue abstraite de la requête, c’est-à-dire une requête générique où les paramètres qui varient entre les requêtes du groupe sont remplacés par N pour un nombre ou S pour une chaîne de caractères, mais aussi un exemple de requête avec des vrais paramètres. C’est un bon point par rapport à mysqldumpslow puisqu’il est facile avec l’exemple de regarder le plan d’exécution donné par la commande EXPLAIN.

Intéressons-nous 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 filtrer.

Chaque requête dans le journal possède un certain nombre de méta-données, comme le temps d’exécution ou le nombre de lignes examinées. Il existe également des méta-données dérivées, comme la moyenne des temps d’exécution pour un groupe de requêtes. Les méta-données disponibles dépendent du type de journal considéré, et tout est détaillé dans la page de la documentation consacrée aux filtres.

mysqlsla nous permet de trier les résultats du rapport selon n’importe quelle méta-donnée avec l’option --sort.

Ceci va nous permettre de répondre aux 2 premières questions :

Quel est le groupe de requêtes ayant le plus long temps de réponse ?

$ mysqlsla -lt slow --sort t_sum msandbox-slow.log

Ici l’affichage est exactement celui que nous avions sans l’option --sort. C’est normal car pour les journaux de requêtes lentes, mysqlsla applique par défaut l’option --sort t_sum !

Quel est le groupe de requêtes ayant le plus grand nombre d’occurrences ?

$ mysqlsla -lt slow --sort c_sum msandbox-slow.log
Report for slow logs: msandbox-slow.log
4 queries total, 2 unique
Sorted by 'c_sum'
Grand Totals: Time 1 s, Lock 0 s, Rows sent 1.80k, Rows Examined 64.18k

_______________________________________________ 001 ___
Count : 3 (75.00%)
Time : 186.368 ms total, 62.123 ms avg, 52.575 ms to 74.232 ms max (20.60%)
Lock Time (s) : 238 s total, 79 s avg, 60 s to 117 s max (47.89%)
Rows sent : 599 avg, 599 to 599 max (100.00%)
Rows examined : 16.04k avg, 16.04k to 16.04k max (75.00%)
Database : sakila
Users :
msandbox@localhost : 100.00% (3) of query, 100.00% (4) of all users

Query abstract:
SET timestamp=N; SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'S' GROUP BY customer_id;

Query sample:
SET timestamp=1278504711;
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-01' GROUP BY customer_id;

________________________________________________ 002 ___
Count : 1 (25.00%)
Time : 718.344 ms total, 718.344 ms avg, 718.344 ms to 718.344 ms max (79.40%)
Lock Time (s) : 259 s total, 259 s avg, 259 s to 259 s max (52.11%)
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 16.04k avg, 16.04k to 16.04k max (25.00%)
Database :
Users :
msandbox@localhost : 100.00% (1) of query, 100.00% (4) of all users

Query abstract:
SET timestamp=N; INSERT INTO rental2 SELECT * FROM rental;

Query sample:
SET timestamp=1278504762;
INSERT INTO rental2 SELECT * FROM rental;

L’utilisation des filtres va nous permettre de répondre aux 2 dernières questions. Il faut savoir que mysqlsla dispose de deux types de filtres : le premier type permet de filtrer sur les méta-données des entrées du journal alors que le second permettre de sélectionner ou d’exclure un ou plusieurs types de requêtes. Ces deux types de filtres peuvent bien sûr être combinés afin de répondre à des questions complexes.

Les filtres sur les méta-données s’écrivent avec l’option --meta-filter (ou -mf en abrégé), comme par exemple -mf "db=sakila" pour ne conserver que les requêtes sur la base sakila ou -mf "db=sakila,c_sum>5" pour ne conserver que les requêtes sur la base sakila qui apparaissent au moins 6 fois.

Il est facile avec cette option de répondre à la 3è question :
Quelles sont les requêtes qui prennent plus de x secondes ?
En positionnant x à 0.1s, on obtient le résultat suivant :

$ mysqlsla -lt slow -mf "t>0.1" msandbox-slow.log
Report for slow logs: msandbox-slow.log
1 queries total, 1 unique
Sorted by 't_sum'
Grand Totals: Time 1 s, Lock 0 s, Rows sent 0, Rows Examined 16.04k

________________________________________________ 001 ___
Count : 1 (100.00%)
Time : 718.344 ms total, 718.344 ms avg, 718.344 ms to 718.344 ms max (100.00%)
Lock Time (s) : 259 s total, 259 s avg, 259 s to 259 s max (100.00%)
Rows sent : 0 avg, 0 to 0 max (0.00%)
Rows examined : 16.04k avg, 16.04k to 16.04k max (100.00%)
Database :
Users :
msandbox@localhost : 100.00% (1) of query, 100.00% (1) of all users

Query abstract:
SET timestamp=N; INSERT INTO rental2 SELECT * FROM rental;

Query sample:
SET timestamp=1278504762;
INSERT INTO rental2 SELECT * FROM rental;

Enfin nous allons nous servir des filtres sur les requêtes (option --statement-filter ou -sf) pour répondre à la 4è question :
Comment ne conserver que les requêtes SELECT ?

$ mysqlsla -lt slow -sf "+SELECT" msandbox-slow.log
Report for slow logs: msandbox-slow.log
3 queries total, 1 unique
Sorted by 't_sum'
Grand Totals: Time 0 s, Lock 0 s, Rows sent 1.80k, Rows Examined 48.13k

________________________________________________ 001 ___
Count : 3 (100.00%)
Time : 186.368 ms total, 62.123 ms avg, 52.575 ms to 74.232 ms max (100.00%)
Lock Time (s) : 238 s total, 79 s avg, 60 s to 117 s max (100.00%)
Rows sent : 599 avg, 599 to 599 max (100.00%)
Rows examined : 16.04k avg, 16.04k to 16.04k max (100.00%)
Database : sakila
Users :
msandbox@localhost : 100.00% (3) of query, 100.00% (3) of all users

Query abstract:
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'S' GROUP BY customer_id;

Query sample:
SELECT customer_id,COUNT(*) FROM rental WHERE return_date>'2005-01-01' GROUP BY customer_id;

Et voilà, notre (courte) exploration de mysqlsla est terminée ! Ces quelques exemples ont montré que mysqlsla est extrêmement flexible comparé à mysqldumpslow, ce qui en fait un très bon choix en tant outil d’analyse de journaux MySQL. Quels sont les inconvénients de mysqlsla ? En fait, je n’en vois qu’un seul : Daniel, le développeur de mysqlsla, a annoncé au printemps que l’outil ne serait plus maintenu. La raison est simple : Daniel fait maitenant partie de l’équipe de développement de Maatkit, qui propose un outil remplaçant mysqlsla. Mais assez dit, ce sera l’objet du prochain article de cette série.

Mots-clefs : , ,

Laisser une réponse