Parsing Mysql Slow Query into Logstash / Kibana

Les « slow-query » logs sont des données importantes dans le but d’optimiser les applications et de diagnostiquer les requêtes dites « lentes ».
Ces fichiers sont présents sur chaque serveur SQL à condition de les avoir activées et lisibles avec n’importe quel éditeur mais il n’est pas nécessaire de rappeler que les données brutes sont difficilement exploitables sauf si nous faisons du cas par cas.

Pour répondre à cette problématique, qui est de pouvoir les lire de façon simple, en agrégeant les requêtes les plus lentes, en pouvant les trier et en les rassemblant en un endroit unique, nous avons procédé à deux méthodes que nous allons détailler ici.

La première consiste à parser directement le flow des requêtes et de les afficher dans Logstash. Quant à la seconde, il s’agit d’abord d’utiliser « pt-query-digest » contenu dans le Percona Toolkit puis de les parser et de les afficher dans Logstash

Mysql Slow Query Log into logstash

La première étape consiste à récupérer les logs via Rsyslog et Syslog-ng, sur le serveur qui contient l’ensemble des logs de nos serveurs. Cette étape a été expliquée dans les articles suivants http://bazarchic.io/?p=16 et http://bazarchic.io/?p=31.

Voici un exemple de requête lente dans son intégralité :

# Time: 161122 16:45:24
# User@Host: user[user] @ [1.2.3.4] Id: 437554863
# Query_time: 0.000546 Lock_time: 0.000141 Rows_sent: 3 Rows_examined: 18
use my_database;
SET timestamp=1479829524;
SELECT *
 FROM langues
 LEFT JOIN pays_langues ON (pays_langues.idlangue = langues.idlangue)
 LEFT JOIN pays_iso ON (pays_iso.idpaysiso = pays_langues.idpays)
 LEFT JOIN categories_exclusion ON (pays_iso.idpaysiso = categories_exclusion.idpaysiso AND categories_exclusion.idcat = '875601')
 WHERE
 pays_iso.status = "on"
 AND categories_exclusion.idpaysiso IS NULL;

Nous partons du fait que les logs sont déjà récupérés depuis les serveurs concernés.
L’étape suivante consiste en la modification de la configuration de Logstash.
Comme à notre habitude, il faut définir une nouvelle section file dans le block input permettant de savoir quels logs nous allons traiter.

# Server001 MySQL Slow LOG
  file {
    path => [ "/srv/syslog/external/server001/*/*/slowlog.log" ]
    type => "server001-slowlog"
    codec => multiline {
        pattern => "^# User@Host:"
        negate => true
        what => "previous"
    }
  }

Ici les logs à traiter sont dans /srv/syslog/external/server001/*/*/slowlog.log, les étoiles correspondent à tous les répertoires entre server001 et le fichier de log.
Nous lui appliquons un type server001-slowlog qui nous permettra de les filtrer.
Nous définissons le format Logstash de log en prenant en compte que les logs à traiter sont redondant et sur plusieurs lignes avec multiline. La partie pattern spécifie l’expression regulière à partir de laquelle le log se répète, quand negate est fixé à true une ligne qui n’est pas matchée avec l’expression régulière est déclassée et non matchée avec le reste des logs. Quant à what, il peut-être previous ou next et indique la relation aux lignes multiples.

La seconde partie à modifier dans le fichier de configuration logstash est la partie filter ou nous allons définir une nouvelle condition en fonction du type.

if [type] == "server001-slowlog" {
  if [message] =~ "^# Time:.*$" {
    drop {}
  }

  grok {
    match => [
    "message", "^# User@Host: %{GREEDYDATA:user}\[%{GREEDYDATA}\] @ %{GREEDYDATA:client_ip} Id: %{GREEDYDATA:id}\s*# Query_time: %{NUMBER:query_time:float} Lock_time: %{NUMBER:query_lock_time:float} Rows_sent: %{NUMBER:query_rows_sent:int} Rows_examined: %{NUMBER:query_rows_examined:int}\s*(?m)SET timestamp=%{NUMBER:timestamp};%{GREEDYDATA:mysql_query}"
    ]
  }

  date {
    match => ["log_timestamp","UNIX"]
  }

  mutate {
    remove_field => "log_timestamp"
    remove_field => "message"
  }
}

La première sous condition permet d’écarter les lignes commençant par # Time:.
La partie grok permet de décomposer le logs sous forme de grande expression regulière avec des patterns pré configurés de Logstash, comme par exemple %{GREEDYDATA:client_ip}, où le pattern GREEDYDATA s’il est matché sera conservé dans le champs client_ip. et ainsi de suite.
La partie date permet de matcher la date avec le format UNIX.
La partie mutate ici permet de reformater les patterns matchés et de les supprimer, de les renommer etc… Dans notre cas de figure, nous les supprimons car la partie message serait redondante étant donné qu’il s’agit du logs brut.
Il est possible de prendre tel quel tout le pattern car il correspond à une slow-query-log de MySQL.

La configuration de logstash est suffisante comme ceci, sa prise en compte nécessite un redémarrage de Logstash.

Dans Elasticsearch il est possible maintenant de consulter les logs avec le parsing adapté.

elasticsearch_logstash

A partir de là, il ne reste plus qu’à construire le dashboard Kibana

MySQL Slow Query Into Logstash with pt-query-digest

Le principe reste le même mais le procédé est différent dans le traitement post réception depuis les serveurs concernés.
En effet, une fois les logs reçus, nous les traiterons avec l’outil de Percona : pt-query-digest. Il est nécessaire de le télécharger et de l’installer à partir des sources officielles : https://www.percona.com/software/database-tools/percona-toolkit

Nous partons également du fait que les fichiers de slow-query logs sont déjà présents sur le serveur de logs.

Voici un exemple de log dans son intégralité :

# Query 1: 2.50 QPS, 0.08x concurrency, ID 0x248E2EADBDB8070F at byte 3489226319
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: 2016-12-01 00:00:07 to 2016-12-07 11:03:45
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 44 1393180
# Exec time 20 46392s 326us 228ms 33ms 56ms 13ms 30ms
# Lock time 22 147s 54us 5ms 105us 167us 40us 93us
# Rows sent 0 2.25M 0 15 1.69 2.90 1.00 0.99
# Rows examine 0 22.15M 8 94 16.67 27.38 5.03 15.25
# Query size 23 738.52M 553 556 555.85 537.02 0 537.02
# String:
# Databases my_database
# Hosts 1.2.3.4 (1393179/99%), localhost (1/0%)
# Users user (1393179/99%), root (1/0%)
# Query_time distribution
# 1us
# 10us
# 100us #
# 1ms #
# 10ms ################################################################
# 100ms #
# 1s
# 10s+
# Tables
# SHOW TABLE STATUS FROM `my_database` LIKE 'dictionnaires_langues'\G
# SHOW CREATE TABLE `my_database`.`dictionnaires_langues`\G
# SHOW TABLE STATUS FROM `my_database` LIKE 'dictionnaires'\G
# SHOW CREATE TABLE `my_database`.`dictionnaires`\G
# SHOW TABLE STATUS FROM `my_database` LIKE 'caracteristiques'\G
# SHOW CREATE TABLE `my_database`.`caracteristiques`\G
# SHOW TABLE STATUS FROM `my_database` LIKE 'produits_group_caracteristiques'\G
# SHOW CREATE TABLE `my_database`.`produits_group_caracteristiques`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT *
 FROM dictionnaires_langues dl
 LEFT JOIN dictionnaires d ON dl.iddictionnaire = d.iddictionnaire
 LEFT JOIN caracteristiques c ON c.iddictionnaire_cle = d.iddictionnaire OR c.iddictionnaire_valeur = d.iddictionnaire
 LEFT JOIN produits_group_caracteristiques pgc ON c.idcaracteristique = pgc.idcaracteristique
 WHERE pgc.idproduit_group = '825316' AND dl.idlangue = '1' AND c.iddictionnaire_cle = '7' AND d.cle = "non"
 ORDER BY c.iddictionnaire_cle ASC, d.cle ASC, pgc.position ASC\G

Nous allons d’abord procéder au parsing des logs avec la commande suivante par exemple

pt-query-digest slowlog.log > parsed_log.log

Le parsing prend plus ou moins de temps en fonction du poids du fichier de log.

/srv/syslog/external/server001/2016/12/slowlog.log: 3% 14:28 remain
/srv/syslog/external/server001/2016/12/slowlog.log: 6% 14:19 remain
/srv/syslog/external/server001/2016/12/slowlog.log: 10% 12:30 remain
[ ... ]
/srv/syslog/external/server001/2016/12/slowlog.log: 91% 00:57 remain
/srv/syslog/external/server001/2016/12/slowlog.log: 96% 00:21 remain

Une fois le fichier formaté, les première lignes ne nous intéressent pas dans le flow que nous voulons traiter.
Pour cela, nous coupons le fichier et conservons uniquement ce qui nous intéresse avec la commande suivante, autrement dit le détail des requêtes.

sed -n '/# Query 1/,$p' parsed_log > server001_slow.log

Nous nous retrouvons ainsi avec un fichier qui correspond à ce que nous voulons.

Libre à vous d’automatiser en cron par exemple ces 2 étapes pour reproduire le principe du flow de la première partie.

A partir de ce moment là, nous reproduisons la configuration du fichier Logstash en prenant en compte le nouveau fichier.

# Server001 MySQL Slow LOG via pt-query-digest
  file {
    path => [ "/srv/syslog/external/server001/*/*/server001_slow.log" ]
    type => "server001-slowlog-pt"
    codec => multiline {
        pattern => "^# Query[ ]{1}[1-9]{1,2}"
        negate => true
        what => "previous"
    }
  }

On remarque que le pattern qui détermine la redondance change car il ne s’agit pas du même type de log.

Voici le block filter qui correspond au nouveau format de log :

if [type] == "bazarchic220-slowlog-pt" {
  grok {
  match => [
    "message", "^# Query %{NUMBER:query_id:int}: %{NUMBER:qps} QPS, %{NUMBER:multiplicator}x concurrency, ID 0x(?<hexa_id>[^ ]*) at byte %{NUMBER:byte}\s*# This item.*$\s*# Scores: V/M = %{NUMBER:vm}\s*# Time range.*$\s*# Attribute.*$\s*# ===.*$\s*# Count[ ]*%{NUMBER:count_pct}.*%{NUMBER:count_total:int}$\s*# Exec time[ ]*(?<exec_time_pct>[^ ]*)[ ]*(?<exec_time_total>[^ ]*)[ ]*(?<exec_time_min>[^ ]*)[ ]*(?<exec_time_max>[^ ]*)[ ]*(?<exec_time_avg>[^ ]*)[ ]*(?<exec_time_95centil>[^ ]*)[ ]*(?<exec_time_stddev>[^ ]*)[ ]*(?<exec_time_median>[^ ]*)\s*# Lock time[ ]*(?<lock_time_pct>[^ ]*)[ ]*(?<lock_time_total>[^ ]*)[ ]*(?<lock_time_min>[^ ]*)[ ]*(?<lock_time_max>[^ ]*)[ ]*(?<lock_time_avg>[^ ]*)[ ]*(?<lock_time_95centil>[^ ]*)[ ]*(?<lock_time_stddev>[^ ]*)[ ]*(?<lock_time_median>[^ ]*)[ ]*\s*# Rows sent[ ]*(?<rows_sent_pct>[^ ]*)[ ]*(?<rows_sent_total>[^ ]*)[ ]*(?<rows_sent_min>[^ ]*)[ ]*(?<rows_sent_max>[^ ]*)[ ]*(?<rows_sent_avg>[^ ]*)[ ]*(?<rows_sent_95centil>[^ ]*)[ ]*(?<rows_sent_stddev>[^ ]*)[ ]*(?<rows_sent_median>[^ ]*)\s*# Rows examine[ ]*(?<rows_examine_pct>[^ ]*)[ ]*(?<rows_examine_total>[^ ]*)[ ]*(?<rows_examine_min>[^ ]*)[ ]*(?<rows_examine_max>[^ ]*)[ ]*(?<rows_examine_avg>[^ ]*)[ ]*(?<rows_examine_95centil>[^ ]*)[ ]*(?<rows_examine_stddev>[^ ]*)[ ]*(?<rows_examine_median>[^ ]*)\s*# Query size[ ]*(?<query_size_pct>[^ ]*)[ ]*(?<query_size_total>[^ ]*)[ ]*(?<query_size_min>[^ ]*)[ ]*(?<query_size_max>[^ ]*)[ ]*(?<query_size_avg>[^ ]*)[ ]*(?<query_size_95centil>[^ ]*)[ ]*(?<query_size_stddev>[^ ]*)[ ]*(?<query_size_median>[^ ]*)\s*# String:\s*# Databases[ ]*(?<databases_database>[^ ]*)\s*# Hosts[ ]*(?<hosts_repartition>.*$)\s*# Users[ ]*(?<users_users>.*$)\s*# Query_time distribution\s*#.*\s*#.*\s*#.*\s*#.*\s*#.*\s*#.*\s*#.*\s*#.*\s*# Tables\s*(?m)%{GREEDYDATA:mysql_query}"
  ]
  }

  mutate {
    remove_field => "message"
  }
}

P.S. : On remarque tout de suite que le pattern permettant de filtrer le log est beaucoup plus conséquent. La petite nuance ici est que nous définisson certains valeur de champs comme des entiers et non des chaines de caractères, car sur Kibana si nous voulons effectuer un tri, les nombres seraient triés comme des chaines de caractère et non des entiers. (1, 10, 101, 2…) au lieu de (1, 2, 10, 101).

La partie « message » est également supprimée car elle serait aussi redondante.

elasticsearch_pt

elasticsearch_pt2

Nous avons automatiser la génération des logs toutes les heures en utilisant pt-query-log depuis les serveurs de base de données.
Nous avons donc établi un dashboard prévu à cet effet et lissé sur 1 heure afin d’avoir toutes les dernières durées à jour.

En espérant que cet article vous ai plus et vous ai servi.

Nicolas Blattmann

Une réflexion au sujet de « Parsing Mysql Slow Query into Logstash / Kibana »

  1. Bonjour,

    Dans ce process d’affichage des logs dans Logstash / Kibana, et plus précisément sur le(s) fichier(s) à récupérer, nous disposons déjà d’un fichier slow-query log et ceci paramétré dans notre my.cnf.

    Votre suggestion me parait tout à fait appropriée et valable dans la mesure où peu importe la manière de générer le fichier source, du moment que nous disposons d’un fichier à traiter.

    Comment verriez-vous le process ?

    Nicolas B.

Laisser un commentaire