Capturer les requêtes sql sur Mariadb / Mysql
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.
[cyklodev_summary]
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 = MonSuperMotDePasseVisiblePartoutAvec 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 dateCe 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.000Je 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 = 3Il ne vous reste plus qu’a appliquer avec un restart du service
systemctl restart mariadbEt 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 :
