Consommation CPU trop importante de MySQL

Imaginez la scène : Vous travaillez au helpdesk, en charge du serveur hébergeant le site web et les base de données de votre entreprise, vous venez de passer un week-end de 3 jours, lundi de Pentecôte oblige, et patratra le bigboss de la boite vous appelle, au bord de la crise de nerf. Le problème ? Le serveur internet dont vous avez la charge est lent ! Très très lent… Votre premier réflexe serait de blâmer les développeur qui ne savent pas écrire une requête SQL propre et performante, mais avant de vous énerver à votre tour, vous vous connecter au serveur. Et là, c’est le drame.. La commande TOP annonce la couleur : Mysqld (le serveur mysql) consomme 553% de cpu (sic!) Autant le dire, tout de suite, c’est le début des ennuis… Premier réflexe, regarder si une requête n’est pas consommatrice de ressource :  

mysql --user=root --password=mot_de_pass_de_root--host=le_serveur_mysql

SHOW FULL PROCESSLIST;

De ce côté là, rien à signaler. Aucune requete consommatrice ou bloqué. Tout semble être en ordre. Jetons un petit coup d’œil à la mémoire. En bon administrateur vous avez développé un petit script (le code est disponible en bas de cet article)

mem.sh mysqld 

Number of processes = 1
Memory usage per process = 224.922 MB
Total memory usage = 224.922 MB

Ici, c’est la même chanson. Rien à signaler. Maintenant les logs :

tail /var/log/kern.log

CPU10: Core temperature above threshold, cpu clock throttled

Ouch… Mysql est VRAIMENT consommateur pour faire chauffer votre Xeon E5 1650. Mais n’ayez pas peur, je ne pense que votre serveur est en train de mettre le feu à l’ensemble de la salle machine ! Et voilà que vous en êtes à faire cette découverte, à deux doigt de faire le 112, que le patron débarque dans le sous-sol de l’IT, tire une chaise et se pose à vos côtés. Histoire de faire bonne figure, vous vérifier que votre serveur n’est pas la cible d’une attaque des Anonymous :

show status like 'Conn%';

1203 connexions, c’est pas mal mais de là faire cramer votre CPU... On continue les recherches :

show status like '%onn%';

Un petit coup d’oeil au status de votre base :

mysqladmin status -h localhost -u root -p

Uptime: 2232
Threads: 46
Questions: 321944
Slow queries: 817
Opens: 2449
Flush tables: 1
Open tables: 400
Queries per second avg: 144.240

Je ne vais pas rentrer dans les détails de chaque valeurs retournées par le commande mysqladmin status, google a déjà la réponse, mais les valeurs que l’on a la font peur ! En bon administrateur, et comme vous avez déjà été confronté à ce genre de problème, vous avez développé des outils d’analyse et d’optimisation. La première étape de votre checklist est de faire un flush/optimisation de toutes vos tables Mysql. Aussi, pour chacune des tables, vous exécutez les commandes suivantes :  

CHECK TABLE
REPAIR TABLE
ANALYZE TABLE
OPTIMIZE TABLE

Avant de continuer, on fait un petit arrêt relance de Mysql :

service mysql stop

[ ok ] Stopping MySQL database server: mysqld.

service mysql start

 

[ ok ] Starting MySQL database server: mysqld . . . ..
[info] Checking for tables which need an upgrade, are corrupt or were
not closed cleanly..

  Après redémarrage et optimisation, il y a du mieux mais le process mysqld monte vitre dans les tours et se remet à consommer du cpu :  

Uptime: 131
Threads: 5 
Questions: 11297 
Slow queries: 1 
Opens: 895 
Flush tables: 1 
Open tables: 400 
Queries per second avg: 86.236

  Vous poursuivez donc vos investigations, via la requête SQL ci-dessous, afin de déterminer à quel moment la consommation CPU augmente :

SHOW FULL PROCESSLIST;

A ce stade, le problème est forcément lié à une requête mal écrite, qui se met à faire un Full scan d’une table. Vous pouvez commencer à souffler car ce ne sera pas votre faute... Comme pour votre script d’optimisation, celui qui fait des optimisations des REPAIR TABLE, ANALYSE TABLE… vous avez un script qui, parcours la base et remonte le nombre de ligne de chaque table, ainsi que le temps pour compter ce nombre de ligne. En exécutant ce script tous les jours, vous pouvez suivre, de loin, l’évolution de la volumétrie de votre base de données. Maintenant, si vous « rapprochez » vos constatations effectué via « SHOW FULL PROCESSLIST » et les tables volumineuses de votre base de données, vous pouvez avoir une idée de ou des tables « à problème » Maintenant que vous avez identifié la source du problème, il ne reste plus qu’à corriger (modifier la structure de la table, ajouter un index, purger certaines donnée obsolètes, modifier le code utilisant cette table…) Dans votre cas, vous remarquez la requête ci-dessous : ( via SHOW FULL PROCESSLIST ) et constatez que son exécution dure 4,5 secondes !

SELECT * FROM visiteur_ip WHERE ip  = 'une_adresse_ip';

La table fait 436 861  lignes et un count(*) s’exécute en 3,3 secondes. Vous appelez donc le « fautif », sous les yeux de votre patron. Celui-ci vous remercie et vous croisez les doigts pour ne plus le voir descendre au sous-sol, le bunker de l’It, avant longtemps ! Le développeur ajoute un index sur sa table, pour optimiser les requêtes et tout est rentre dans l'ordre !

ALTER TABLE `visiteur_ip` ADD INDEX(`ip`);

Et voila ! Une folle aventure, de quoi bien démarrer la semaine, qui se termine bien ! Toute ressemblance avec des personnages existant ou ayant existé serait fortuite et des situations existants serait pure coïncidence due au hasard. Ou pas...     Quelques sources et références utilisées pour cet article :

• http://alvinalexander.com/blog/post/mysql/how-show-open-database-connections-mysql
• https://blog.mozilla.org/it/2012/06/30/mysql-and-the-leap-second-high-cpu-and-the-fix/
• http://stackoverflow.com/questions/1282232/mysql-high-cpu-usage
• http://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html
• http://dev.mysql.com/doc/refman/5.7/en/show-processlist.html
• http://tinyurl.com/mysql-cpu

Le code du script mem.sh :

#!/bin/bash
ps -C $1 -O rss | gawk '{ count ++; sum += $2 }; END {count --; print "Number of processes =",count; print "Memory usage per process =",sum/1024/count, "MB"; print "Total memory usage =", sum/1024, "MB" ;};'