Tracer les requêtes MySQL en cours d’exécution

S’il est relativement aisé de débugger une application en cours de développement ou lors des phases de preprod, c’est une toute autre histoire lorsque celle-ci est en production, et que l’on doit continuer à servir les pages aux internautes sans (trop) dégrader l’applicatif. L’un des problèmes majeurs, si cela n’a pas été prévu en amont ou lors des tests unitaires, est de traquer ce que doit traiter MySQL à un instant T pour comprendre pourquoi mysqld utilise, par exemple, plus de 50% du CPU. En effet, les 3/4 des soucis de performance que nous rencontrons sur les développements sont dus à des requêtes mal pensées ou mal utilisées.

Dans le cadre d’un récent développement par un prestataire, nous avons eu à auditer une application qu’il a livré. Celle-ci avait une architecture relativement simple: Flex pour l’interface utilisateur, PHP propulsé par un Framework dont je tairais le nom pour traiter les actions de l’utilisateur, et ce dernier fait donc exécuter les requêtes MySQL pour servir le contenu au Flex. Au delà de ça, diverses choses comme du chat et de la webcam sont traitées par un serveur de streaming propriétaire d’Adobe: Flash Media Server (FMS pour les intimes). Le contexte d’analyse est simple: « tout se passait bien jusqu’au jour de la mise en beta », jour à partir duquel il a été mis à disposition d’un bien grand nombre d’internautes des invitations « privées », information relayée par quelques tweets de bloggeurs influents, tout ceci histoire de lancer paisiblement la machine. Ce jour là les classiques ont été constatés: charge apache, charge MySQL, SWAP et le tout s’est terminé en beauté par un magnifique segfault de FMS.

Afin de faire comprendre au prestataire que les soucis de performance n’étaient ni du:

  • à une incroyable et incontrôlable explosion du trafic sur le serveur
  • à l’incompétence du sysadmin
  • à un comportement ésotérique du serveur
  • au sous dimensionnement du hardware (pour cette partie en tout cas) [1]
  • à bien d’autres choses…

nous avons décidé de sortir sur un laps de quinze minutes les requêtes que devait exécuter MySQL. Ça c’était pour la théorie, maintenant quelle solution choisir ?

  1. Utiliser munin
    Munin ne nous aurait donné qu’une statistique générale du nombre de requêtes à traiter à un instant, sans nous en extraire le contenu. En effet, si l’on se penche sur le plugin mysql_queries de munin situé dans /usr/share/munin/plugins/, on observe qu’il ne fait qu’utiliser mysqladmin avec l’argument extended-status:

  2. Utiliser le query log de MySQL
    Inenvisageable au moins pour deux raisons: nous étions en production, et donc pas envie de faire une erreur de configuration, aussi minime soit-elle. Mais surtout activer les logs de MySQL, sans savoir précisément de quoi il en retourne derrière (en volume de requêtes), c’est un coup à aggraver la situation en faisant exploser les I/O et par la même d’augmenter l’overhead de la machine. Le /etc/mysql/my.cnf est d’ailleurs plutôt clair à ce sujet:

  3. Utiliser le slow query log de MySQL
    Il ne recense que les requêtes qui prennent plus d’une seconde. Le problème est que la plupart des soucis de performance ne viennent pas de requêtes trop longues, mais simplement de requêtes qui sont exécutées très souvent, par exemple dans une boucle au lieu d’utiliser un JOIN.
  4. Utiliser le log binaire de MySQL
    Utilisation inappropriée: il enregistre l’intégralité des changements et est généralement utilisé pour la réplication, du fait de son contenu et de son format.
  5. Utiliser SHOW PROFILES
    Malheureusement, il ne fait état que des ressources, ne gère pas l’intégralité des requêtes et doit surtout être gourmand.
  6. Utiliser le patch de Google user_statistics
    Cette solution semble réellement viable pour analyser les performances par utilisateur, mais cela ne collait pas du tout à l’utilisation que je souhaitais en faire. Et ce n’était de toute façon pas déployé sur la machine.
  7. Utiliser Mysql Proxy
    Cette solution est réellement idéale, elle embarque load balancing, failover, query analysis, query filtering,… avec de beaux charts. Malheureusement, même tarif que pour les logs cités précédemment: On ne déploie pas cela sur de la prod lorsqu’il est trop tard.

Toutes ces solutions semblaient efficaces pour benchmarker au global un applicatif, un utilisateur, ou pour analyser les requêtes au globale, mais pas pour faire un snapshot à un instant T sans mettre le serveur à genoux. Il existait un solution un peu bâtarde connue de tous:

La commande showprocesslist

Cette commande affiche la liste des requêtes en cours d’exécution. Pour chaque requête, vous pouvez voir en combien de temps celle-ci a été exécutée, son utilisateur et son état. Le soucis est que le snap est fait à l’instant précis où l’on tape la commande. En d’autre terme, je ne connais QUE la requête qui est exécutée précisément à CET instant. Je ne connais ni celle d’avant, ni celle d’après. C’est évidement la grosse limitation de cette méthode. Son avantage est en revanche d’être présent nativement sur toutes les versions de MySQL. On pouvait donc imaginer réunir les requêtes à l’aide un bête script:

Pour le coup cette méthode ne m’a rien apporté de concluant:

Je n’ai trouvé que deux solutions pour réussir à faire ce dont j’avais besoin, mais ces deux solutions sont globalement les mêmes, elles utilisent la même méthode et le même principe: sniffer ce qui se passe sur le port 3306, port d’écoute de MySQL.

Utilisation de tcpdump

J’ai donc entrepris de sniffer ce qui arrivait sur le 3306 avec tcpdump/libpcap à l’aide de la commande suivante [2]:

Celle-ci affichera en interactif l’intégralité des requêtes qui sont soumises à MySQL. Cette méthode n’a rien donné dans un premier temps: les fichiers de configuration utilisaient localhost comme hôte de connexion. J’ai donc du modifier l’hôte en 127.0.0.1 pour passer par la network stack. Et là, Ô joie, toutes les requêtes processées par MySQL s’empilent les unes aux autres dans mon shell.

Utilisation de mysqlsniffer

Cette méthode est plus commode pour le néophyte, et elle permet de dumper efficacement la requête, mais également la réponse de MySQL. Pour l’utiliser, voici la marche à suivre:

Après il n’y a plus qu’à:

Allez, pour le plaisir des yeux, une requête parmi tant d’autres que j’ai pu trouver lors du dump. Elle est exécutée à chaque inscription, ou à chaque modification dans le profil de l’utilisateur, la grande classe. Bah quoi, elle est sujette à changer souvent cette liste. Ce que vous êtes médisants.

Au fait, pour ceux qui croient que le blog est en friche, j’ai sorti la tondeuse.
[1]Il faut quand même de sacrés machines pour faire tenir 500 pelos sur un serveur.
http://www.adobe.com/devnet/flashmediaserver/articles/performance_tuning_webcasts.html
[2]Merci à Brian Racer.

Partagez cet article !

    4 thoughts on “Tracer les requêtes MySQL en cours d’exécution

    1. Ubrette dit :

      Bonjour,
      Pourriez-vous m’indiquer où je dois changer le localhost par 127.0.0.1 car ça ne m’affiche rien avec mysqlsniffer ? le bind-address du my.cnf ? Si c’est cela il est déjà à 127.0.0.1 et pourtant rien !!

    2. John JEAN dit :

      Dans votre fichier de configuration de l’application pardi !

    3. Thierry dit :

      Merci c’est exactement ce que je recherchais… Je vais envoyer ça à mon programmeur.

    Laisser un commentaire

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