Résumé : si tu journalises les requêtes lentes avec le paramètre slow_query_log
de MariaDB / MySQL, attention à log_slow_rate_limit
(qui est désactivé par défaut), car, avec lui, seule une fraction des requêtes sera analysée et, si besoin, journalisée. Avec « log_slow_rate_limit = 10 », seule la dixième requête sera analysée et, si elle est lente, journalisée. Dans une séquence "4 requêtes OK suivies par 3 requêtes lentes suivies par 3 requêtes OK", les trois requêtes lentes passent inaperçues.
Sur l'un de nos serveurs MariaDB, mysqladmin status
nous informe qu'il y a des requêtes lentes / slow queries. Une requête lente est une requête dont la durée d'exécution dépasse la valeur du paramètre long_query_time (10 secondes par défaut).
Nous journalisons les requêtes lentes avec les paramètres suivants dans /etc/mysql/mariadb.conf.d/60-surchargeLocale.cnf (cela permet qu'une mise à jour des paquets mette à jour les paramètres généraux dans 50-server.cnf sans affecter les paramètres que nous savons essentiels / vitaux pour nos besoins + de simplifier l'usage de Puppet puisqu'il suffit de déposer le fichier au lieu de modifier l'autre avec file_line ou concat ou…) :
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mariadb-slow.log
Je regarde donc le journal sus-mentionné : il est vide ! O_O
J'utilise le client en ligne de commande, mysql
afin d'exécuter la requête « SELECT SLEEP(12); » (ben quoi, il s'agit d'une requête dont l'exécution va durer plus de 10 secondes). Elle n'est pas journalisée. mysqladmin
nous mentirait ?
Après m'être cassé les dents, il s'avère que le paramètre log_slow_rate_limit
, qui n'est pas activé par défaut dans Debian GNU/Linux ni sur nos autres serveurs, était activé sur ce serveur.
Je n'y avais pas pris garde car, dans les autres logiciels que je connais, comme OpenVPN, la limitation du débit signifie que le logiciel arrête de journaliser quand un même message d'erreur se répète X fois. log_slow_rate_limit
fonctionne à l'envers : seule une fraction des requêtes sera analysée et, si elle est trop longue, alors la requête sera journalisée.
Avec « log_slow_rate_limit = 10 », seule 1 requête sur 10 sera analysée. Ainsi, si 8 requêtes OK sont suivies par deux requêtes lentes, alors la journalisation s'activera au bout de la deuxième requête lente. Si 13 requêtes sont OK puis 7 foireuses, la journalisation s'activera au bout de la 7e requête (13 + 7 + 20 qui est un multiple de 10). Autant dire que si t'as une séquence de la forme "4 requêtes OK suivies par 3 requêtes lentes suivies par 3 requêtes OK", tu vas attendre longtemps la journalisation, même si la connexion au serveur, la commande jouée à la connexion, etc. (qui sont considérées comme des requêtes) ajoutent de l'entropie.
Dans mon cas, la valeur de log_slow_rate_limit
était 1000, donc, forcément, il fallait attendre loooongtemps avant qu'une requête soit journalisée.