Tutorial PHP : chronométrer le temps de calcul des requêtes SQL (benchmark)

Pour ceux qui ne l’auraient pas encore, voici la fameuse recette du benchmark maison au coulis de microtime. Ou comment chronométrer le temps de calcul imposé au serveur par chacune des séquences de votre script. Cela permet de repérer les goulets d’étranglement, qu’il s’agisse de requêtes SQL ou de boucles de code PHP mal optimisés.

Il y a quelques temps, sur notre intranet, j’ai eu affaire à d’importants ralentissements sur l’ensemble des pages. J’étais à peu près sûr qu’il s’agissait d’une requête SQL mal optimisée ou de son traitement dans une boucle PHP trop lourde. Cependant, le site étant un bric-à-brac maison constitué de nombreux modules indépendants (actus, annuaire, gestion de tickets, tableaux de bord statistiques), le problème pouvait provenir de n’importe lequel des 25 fichiers d’include chargés dynamiquement. J’avais donc besoin d’évaluer le temps consacré par le serveur à chacune des requêtes pour identifier la ou les fautives.

Il y a des outils PHP dédiés au benchmarking. Mais je n’avais (comme souvent) pas le courage de me lancer dans le déploiement d’une usine à gaz comme Pear pour une simple classe qui fait des soustractions, à en lire la documentation et à comprendre sa logique différente de la mienne. J’ai donc cherché une solution vite-fait mal-fait permettant de cerner les coupables de manière progressive, sans prise de tête.

Recette du benchmark maison au coulis de microtime

Le principe est simple : placer des marqueurs qui donnent l’heure tout au long du script en mesurant le nombre de microsecondes écoulées depuis le précédent. C’est bête et basique, et je pourrais en rester là. Mais je vais vous donner les ingrédients qui tiennent en deux fonctions très simples et quelques print bien placés.

Ingrédients

• une fonction qui donne l’heure (à placer dans vos includes)

  function getmicrotime()
  {
      // découpe le tableau de microsecondes selon les espaces
      list($usec, $sec) = explode(" ",microtime());
      // replace dans l'ordre
      return ((float)$usec + (float)$sec);
  }

•  

• une fonction qui affiche le temps écoulé

  /** *@desc Affiche le temps écoulé (en microsecondes) depuis la dernière étape.
  * L'argument $nom_etape permet de spécifier ce qui est mesuré (ex. "page de stats" ou "requête numéro 7") */
  function benchmark ($nom_etape)
  {
      global $etape_prec;
      $temps_ecoule = ($etape_prec) ? round((getmicrotime() - $etape_prec)*1000) : 0;
      $retour = '<p class="alerte">' . $nom_etape . ' : ' . $temps_ecoule . 'ms</p>';
      $etape_prec = getmicrotime();
      return $retour;
  }

   

• des marqueurs répartis après les principales requêtes

  Lorsque vous placez un marqueur avec print benchmark(‘pointeur’);, le script va calculer le temps écoulé depuis le dernier appel et l’afficher dans la page Web. Deux marqueurs peuvent suffire pour benchmarker une page : un au début et un à la fin. Mais l’idéal c’est d’en rajouter à différentes étapes de la page pour « resserrer » la recherche autour d’une partie spécifique.

  include("modules/mod_actus.php");
  print benchmark("Module actus"); 
  // renvoie Module actus : 26 ms 
  
  include("modules/mod_contacts.php");
  print benchmark("Module contacts"); 
  // renvoie Module contacts : 47 ms 
  
  include("modules/mod_stats.php");
  print benchmark("Module stats"); 
  // renvoie Module stats : 1289 ms

  Dans l’exemple ci-dessus, on identifie rapidement que le module stats effectue un traitement anormalement long, ce qui permet de se concentrer sur le script en question (mod_stats.php). A l’intérieur de ce script, on pourra placer de nouveaux marqueurs pour « resserrer » le filet autour de la requête fautive :

  mysql_query($requete1);
  print benchmark("Requête 1"); 
  // renvoie Requête 1 : 82 ms 
  
  mysql_query($requete2);
  print benchmark("Requête 2");
  // renvoie Requête 2 : 1013 ms 
  
  mysql_query($requete3);
  print benchmark("Requête 3"); 
  // renvoie Requête 3 : 94 ms

   

  Voilà ! Nous avons cerné le coupable, qui met plus d’une seconde à s’effectuer. Il ne reste plus qu’à optimiser la requête pour alléger le script, ou à se passer de cette fonctionnalité si elle est décidément trop gourmande.

Conseils de cuisson

• Attention ! Le temps de calcul rapporté est uniquement celui nécessaire à la génération du script par le serveur. Il n’inclut pas le temps d’envoi de la requête par le client, celui de l’envoi des données générées par le serveur ou encore le temps de mise en forme de la page par le navigateur du visiteur (qui peut être important s’il y a beaucoup de javascript, styles CSS complexes, etc.).
• Attention à ne pas oublier un marqueur en route. Sinon le décompte du temps intitulé « Module 5″ pourrait bien recouvrir les modules 3, 4 et 5…
• Pour masquer le benchmark aux utilisateurs et le réserver aux admins de l’intranet, je passe ma variable $utilisateur en global dans la fonction benchmark(), et je vérifie que $utilisateur->possedeDroits(‘admin’) avant de renvoyer $retour
• L’usage de print peut provoquer une erreur avant l’envoi des en-têtes HTTP (« headers already sent by… »). Placez la première juste après les headers ou utilisez l’output buffering.

Ranger les ustensiles

Une fois le benchmarking effectué, vous pouvez supprimer l’ensemble des marqueurs insérés dans les scripts pour le désactiver. Mais si vous êtes un fainéant (comme moi) ou que vous pensez qu’ils vont resservir, il est plus rapide de désactiver simplement l’affichage des valeurs de retour en plaçant en commentaire la ligne // return $retour ; de la fonction benchmark. Il suffira de le réactiver à la prochaine occasion.

A vos fourneaux !