Capturer les requêtes sql sur Mariadb / Mysql

sql query

A la fin de cet article vous trouverez rapidement les requêtes sql qui passent sur votre serveur mariadb ou mysql et vous pourrez isoler celles qui posent problème dans un log ou même les voir en temps réel.

Quand une instance mariadb (ou mysql) met du temps à répondre pour une requête, il est souvent compliqué de savoir ce qui ne va pas. Il faut en premier lieu récupérer les requêtes qui passent. Voici une liste de possibilités pour y voir plus clair.



Voir les requêtes en cours

Je vais détailler 2 possibilités qui sont toutes les deux basées sur la même requête.

Simuler une requête longue

Pour avoir le temps de voir l’exécution de la requête, j’utilise la fonction benchmark pour faire une requête longue.

On commence par lancer le benchmark comme ceci

mysql -u root
MariaDB [(none)]> select benchmark(100000000, md5('This is a very long query simulated by benchmark '));

Une commande pour voir les requêtes

Pour avoir les résultats suivant, je vous conseille d’avoir 2 shell ouverts: l’un pour lancer le benchmark et un autre pour lancer la commande processlist.

Tout de suite après avoir lancé le benchmark, dans l’autre shell, on lance cette commande show processlist :

mysql -u root
MariaDB [(none)]> show processlist;
+-------+-------------+-----------+------+---------+------+--------------------------+---------------------------------------------------------------------------------------+----------+
| Id    | User        | Host      | db   | Command | Time | State                    | Info                                                                                  | Progress |
+-------+-------------+-----------+------+---------+------+--------------------------+---------------------------------------------------------------------------------------+----------+
|     1 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                  |    0.000 |
|     2 | system user |           | NULL | Daemon  | NULL | InnoDB purge coordinator | NULL                                                                                  |    0.000 |
|     3 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                  |    0.000 |
|     4 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                  |    0.000 |
|     5 | system user |           | NULL | Daemon  | NULL | InnoDB shutdown handler  | NULL                                                                                  |    0.000 |
| 11593 | root        | localhost | NULL | Query   |    6 | Executing                | select benchmark(100000000, md5('This is a very long query simulated by benchmark ')) |    0.000 |
| 11595 | root        | localhost | NULL | Query   |    0 | Init                     | show processlist                                                                      |    0.000 |
+-------+-------------+-----------+------+---------+------+--------------------------+---------------------------------------------------------------------------------------+----------+
7 rows in set (0.007 sec)

Je trouve bien ma requête de benchmark qui est en cours d’exécution.

Tronquage des requêtes

Si vous êtes sur un système opérationnel il y a de fortes chances que vous traquiez une requête très longue (en taille) avec probablement des jointures.

L’affiche risque de ne pas suivre, car la colonne INFO est tronquée, il faut alors ajouter FULL dans la commande.

Pour simuler ça, j’utilise cette commande de benchmark:

select benchmark(100000000, md5('This is a very long query simulated by benchmark ! Do not use this on a production server ! It can really slow down the queries. Please be sure to add FULL to the alias'));

Voila le résultat vu comme avant, avec la colonne tronquée :

MariaDB [(none)]> show processlist;
+-------+-------------+-----------+------+---------+------+--------------------------+------------------------------------------------------------------------------------------------------+----------+
| Id    | User        | Host      | db   | Command | Time | State                    | Info                                                                                                 | Progress |
+-------+-------------+-----------+------+---------+------+--------------------------+------------------------------------------------------------------------------------------------------+----------+
|     1 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                 |    0.000 |
|     2 | system user |           | NULL | Daemon  | NULL | InnoDB purge coordinator | NULL                                                                                                 |    0.000 |
|     3 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                 |    0.000 |
|     4 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                 |    0.000 |
|     5 | system user |           | NULL | Daemon  | NULL | InnoDB shutdown handler  | NULL                                                                                                 |    0.000 |
| 11595 | root        | localhost | NULL | Query   |    0 | Init                     | show processlist                                                                                     |    0.000 |
| 11596 | root        | localhost | NULL | Query   |   16 | Executing                | select benchmark(100000000, md5('This is a very long query simulated by benchmark ! Do not use this  |    0.000 |
+-------+-------------+-----------+------+---------+------+--------------------------+------------------------------------------------------------------------------------------------------+----------+
7 rows in set (0.006 sec)

Et le résultat en rajoutant FULL :

MariaDB [(none)]> show full processlist;
+-------+-------------+-----------+------+---------+------+--------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| Id    | User        | Host      | db   | Command | Time | State                    | Info                                                                                                                                                                                                        | Progress |
+-------+-------------+-----------+------+---------+------+--------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
|     1 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                                                                                                                        |    0.000 |
|     2 | system user |           | NULL | Daemon  | NULL | InnoDB purge coordinator | NULL                                                                                                                                                                                                        |    0.000 |
|     3 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                                                                                                                        |    0.000 |
|     4 | system user |           | NULL | Daemon  | NULL | InnoDB purge worker      | NULL                                                                                                                                                                                                        |    0.000 |
|     5 | system user |           | NULL | Daemon  | NULL | InnoDB shutdown handler  | NULL                                                                                                                                                                                                        |    0.000 |
| 11595 | root        | localhost | NULL | Query   |    0 | Init                     | show full processlist                                                                                                                                                                                       |    0.000 |
| 11596 | root        | localhost | NULL | Query   |   43 | Executing                | select benchmark(100000000, md5('This is a very long query simulated by benchmark ! Do not use this on a production server ! It can really slow down the queries. Please be sur to add FULL to the alias')) |    0.000 |
+-------+-------------+-----------+------+---------+------+--------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
7 rows in set (0.004 sec)

Utiliser SQL à la place de la commande

Pour avoir un peu de granularité, on peut faire la requête en SQL pur, on a alors la possibilité de filtrer un peu plus le résultat. (pensez à relancer le benchmark si il s’est terminé).

A noter que si vous utilisez la forme SQL, vous aurez d’office intégralité de la requête, pas de colonne tronquée.

MariaDB [(none)]> SELECT USER,COMMAND,INFO FROM INFORMATION_SCHEMA.PROCESSLIST;
+-------------+---------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| USER        | COMMAND | INFO                                                                                                                                                                                                        |
+-------------+---------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| root        | Query   | select benchmark(100000000, md5('This is a very long query simulated by benchmark ! Do not use this on a production server ! It can really slow down the queries. Please be sur to add FULL to the alias')) |
| root        | Query   | SELECT USER,COMMAND,INFO FROM INFORMATION_SCHEMA.PROCESSLIST                                                                                                                                                |
| system user | Daemon  | NULL                                                                                                                                                                                                        |
| system user | Daemon  | NULL                                                                                                                                                                                                        |
| system user | Daemon  | NULL                                                                                                                                                                                                        |
| system user | Daemon  | NULL                                                                                                                                                                                                        |
| system user | Daemon  | NULL                                                                                                                                                                                                        |
+-------------+---------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
7 rows in set (0.004 sec)

Surveiller les requêtes en temps réel

Maintenant qu’on sait voir les requêtes en cours, on va éviter d’appuyer frénétiquement sur exécuter ou haut+entrée , et utiliser la commande watch. Je commence par un aparté pour le mot de passe.

Gestion du mot de passe

Dans le shell, le mot de passe est demandé en mode interactif, en spécifiant l’argument -p comme ceci.

mysql -u root -p
Enter password: ************
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 11599
Server version: 10.3.22-MariaDB MariaDB Server
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
MariaDB [(none)]>

Il est également possible de mettre le mot de passe dans la commande, mais c’est très vivement déconseillé car visible dans l’historique mais aussi en listant les process …

mysql -u root -pMonSuperMotDePasseVisiblePartout
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 11599
Server version: 10.3.22-MariaDB MariaDB Server
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
MariaDB [(none)]>

Si vraiment vous voulez le faire, notez bien qu’il n’y a pas d’espace en le -p et MonSuperMotDePasseVisiblePartout .

Mais il y a une manière de propre de faire ça en créer un fichier .my.cnf

vi $HOME/.my.cnf
[mysql]
user = root
password = MonSuperMotDePasseVisiblePartout

Avec ce fichier dans le home de votre user, mysql ira de suite lire ce fichier pour récupérer le mot de passe. Vous pouvez aussi étendre ce fichier avec [mysqladmin] ou [mysqldump].

mysql -u root
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 11599
Server version: 10.3.22-MariaDB MariaDB Server
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
MariaDB [(none)]>

Le temps réel avec watch

Maintenant qu’on a réuni toutes les briques, place au temps réel. Pour ca, j’utilise la commande watch qui exécute une commande à intervalle régulier.

Voici un exemple d’affichage de la date avec un rafraichissement toutes les 3 secondes.

watch -n 3 date

Ce qui nous intéresse, c’est de lancer la commande show processlist.

watch -n 1 "mysql -u root -e 'show processlist'"
Every 1.0s: mysql -u root -e 'show processlist'                                                                                                                                  Tue Jul 28 02:21:20 2020

Id      User    Host    db      Command Time    State   Info    Progress
1       system user             NULL    Daemon  NULL    InnoDB purge coordinator        NULL    0.000
3       system user             NULL    Daemon  NULL    InnoDB purge worker     NULL    0.000
2       system user             NULL    Daemon  NULL    InnoDB purge worker     NULL    0.000
4       system user             NULL    Daemon  NULL    InnoDB purge worker     NULL    0.000
5       system user             NULL    Daemon  NULL    InnoDB shutdown handler NULL    0.000
38543   booa    sqlsrv.cyklodev.lan:57801  CKD    Sleep   4181            NULL    0.000
39357   root    localhost       NULL    Query   0       Init    show processlist        0.000

Je vous conseille de ne pas mettre le full dans la commande, car l’affichage risque d’en pâtir car sur une base utilisée, il devrait y avoir pas mal d’activité.

Tracer les requêtes longues

Il est évident qu’on est pas forcement devant son terminal au moment ou les ennuis arrivent, du coup il y a possibilité de mettre de coter les requêtes longues.

Définition d’une requête longue

La valeur par défaut d’un requête longue est définie dans les variables, et vous pouvez les vérifier comme cela. Ici la valeur est a 10 secondes.

MariaDB [(none)]> SHOW VARIABLES LIKE 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+

On va modifier ce délai par 2 secondes comme ceci

SET GLOBAL long_query_time = 2;

Et on vérifie que c’est bien pris en compte

MariaDB [(none)]> SHOW VARIABLES LIKE 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 2.000000 |
+-----------------+----------+
1 row in set (0.001 sec)

Fichier de log

Il faut ensuite activer et définir le fichier de log. Ces 2 valeurs sont slow_query_log et slow_query_log_file. On voit en dessous les valeurs par defaut.

MariaDB [(none)]> SHOW VARIABLES LIKE 'slow%' ;
+---------------------+--------------+
| Variable_name       | Value        |
+---------------------+--------------+
| slow_launch_time    | 2            |
| slow_query_log      | OFF          |
| slow_query_log_file | eye-slow.log |
+---------------------+--------------+

Changeons cela, en activant le logging.

SET GLOBAL slow_query_log = 'ON';

On relance le benchmark suivant qui dure un peu plus de 2 secondes:

MariaDB [(none)]> select benchmark(10000000, md5('This is a very long query simulated by benchmark '));
+-------------------------------------------------------------------------------+
| benchmark(10000000, md5('This is a very long query simulated by benchmark ')) |
+-------------------------------------------------------------------------------+
|                                                                             0 |
+-------------------------------------------------------------------------------+
1 row in set (2.733 sec)

Mais ou est donc le log ! De base, il sera dans le « home » des datas de mariadb (mysql) : /var/lib/mysql/eye-slow.log . Attention, pour que le fichier soit généré, il faut que le user mysql (et cela même avec mariadb) ai les droits d’écriture. Je vais le mettre dans /tmp/ avec cette commande

SET GLOBAL slow_query_log_file = '/tmp/slow_mysql.log';

On peut voir le contenu qui capture non seulement la requête mais également le volume de données qui sont brassées.

cat /tmp/slow_mysql.log
/usr/sbin/mysqld, Version: 10.3.22-MariaDB (MariaDB Server). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                Id Command  Argument
# Time: 200728 02:16:39
# User@Host: root[root] @ localhost []
# Thread_id: 11601  Schema:   QC_hit: No
# Query_time: 2.732669  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
# Rows_affected: 0  Bytes_sent: 132
SET timestamp=1595952999;
select benchmark(10000000, md5('This is a very long query simulated by benchmark '));

Il y a aussi la possibilité de logger les requêtes qui n’utilisent pas d’index et qui sont par nature très couteuses.

Configuration persistante

On a pour l’instant que modifier les variables par défaut, et si on redémarre le serveur, notre configuration n’y sera plus.

Si vous voulez cette configuration permanent, vous pouvez éditer le fichier my.cnf

vi /etc/my.cnf
...
[mysqld]
slow_query_log = 1
long_query_time = 3

Il ne vous reste plus qu’a appliquer avec un restart du service

systemctl restart mariadb

Et maintenant, pourquoi c’est lent ?

Capturer la requête c’était la partie facile, maintenant il va falloir comprendre pourquoi c’est lent. Et là, c’est un métier à part. On sort du cadre du sysadmin pour rentrer dans l’univers merveilleux du DBA (databases admin).

Expliques moi la requête

Maintenant qu’on a une requête, il suffit de rajouter le mot clé EXPLAIN ou ANALYZE devant, et de l’exécuter pour avoir le plan détaillé de la requête.

Faire de l’analyse de requête est vraiment un sujet à part, et à défaut de l’écrire moi même, je vous renvoie vers l’excellent article de seboss666 . Même s’il est un peu ancien, il est toujours d’actualité.

Si vous voulez creuser le sujet voici quelques liens :

MariaDB Analyze

MySQL Analyze

Zephilou

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée. Les champs obligatoires sont indiqués avec *

Post comment