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 !

Outil de référencement professionnel - essai gratuit Ce contenu a été publié dans Développement PHP, avec comme mot(s)-clé(s) , , , , , . Vous pouvez le mettre en favoris avec ce permalien.

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

  1. Il y a quelques jours tu faisais l’éloge de la POO…

    Pourquoi ne pas modifier la fonction "requete()" ?

  2. Damien Ravé (le Caphar) dit :

    Je n’ai pas de religion en matière de technologie : à chaque tâche son outil. Si j’apprécie la programmation orientée objet pour exécuter des opérations complexes et répétitives (traiter des Articles, des Rubriques, des Utilisateurs), la méthode procédurale est tout à fait appropriée pour des fonctions plus légères. Dans le cas présent, je ne vois pas l’avantage de créer une classe. A part peut-être pour éviter le passage d’une variable globale jamais idéale, mais c’est un moindre mal.

    Cela dit, si tu me proposes une syntaxe vraiment plus légère que ce que j’ai proposé, je suis preneur.

  3. Imaginons que dans ta classe SQL tu aies une fonction query($requete) { return mysql_query($requete); }

    Maintenant tu la modifies :
    query($requete) { $t=getmicrotime(); $q = mysql_query($requete); $t=getmicrotime()-$t; return $q; }

    Enfin c’est surtout pour le principe que je mets ce bout de code qui n’en est pas un.

    En gros voici le principe de ma fonction q() (qui est une fonction et non une méthode puisque je n’ai pas trouvé d’intérêt à utiliser une classe) :
    – stocker la requête, le fichier et la ligne où elle est exécutée (merci debug_backtrace())
    – démarrer le chrono
    – faire la requête
    – stoper le chrono, stocker le temps d’exécution de la requête

    En fin de script, je n’ai plus qu’à afficher mon tableau rempli au cours du traitement.

    Ca permet de faire des stats sympa, tu peux voir ce que j’en fais sur link to sens-interdit.fr (tout en bas, il faut cliquer sur le texte indiquant les différentes mesures pour afficher les requêtes et leur temps)

Laisser un commentaire

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