(PHP) Mesurer les performances et deboguer un script php

La correction des erreurs et l'amélioration des performance d'un script PHP font partis des missions d'un développeur d'application. En fonction du type de logiciel que l'on est entrain de concevoir la recherche d'erreur et l'optimisation des temps d’exécution peuvent être très important. En ce qui concernent la détection des warning et autres messages d'alertes, le moteur PHP remonte efficacement les erreurs et les informations de débogage.
Cet article traite tout particulièrement la recherche des portions de scripts PHP qui ralentissent l'application.

Rechercher les lenteurs d'un script PHP

En plein développement d'une application PHP, l’exécution des classe paraisse longue alors que pour l'instant les données sont assez faibles. Ce logiciel a pour vocation de tourner en aveugle sur un serveur Linux sous Apache et avec de gros volumes de données.
Qu'est ce qui ralentit l'application et dans quelle partie chercher les optimisations de performance de script PHP ?
A la mano, en regardant certaines portions du code, la recherche de ce qui ralentit l’exécution va être longue. De plus, l'application est construire suivant le modèle MCV et un petit réseau de neurone.
La solution ? développer une classe PHP de type Singleton qui peut être utilisée de manière statique et qui a pour but de :
1. chronométrer un labs de temps entre 2 points d’arrêt,
2. cumuler le temps d’exécution d'un type de tâche.

<?php
/**
* Mesurer les performances et deboguer un script php
* http://www.fobec.com/php5/1180/mesurer-performances-deboguer-script-php.html
* @author Fobec 06/2016
*/
class Debug_Logger {
 
//Singleton: instance de la class
protected static $instance;
//Tableau pour stocker les données
static private $time_line_firststamp = array();
static private $time_line_laststamp = array();
static private $time_line = array();
static private $time_pool = array();
static private $time_periods = array();
 
/**
* Constructeur
*/
private function __construct() {
/* pas besoin dans ce cas */
}
 
/**
* Singleton: instance à partir d'un contexte statique
* @return type
*/
static public function getInstance() {
if (!isset(self::$instance)) {
self::$instance = new self;
}
 
return self::$instance;
}
 
/**
* Clonage non utilisé
*/
private function __clone() {
/* do nothing here */
}
 
/**
* Remettre à zéro
*/
static public function reset() {
self::$instance = null;
self::$time_periods = array();
self::$time_pool = array();
}
 
/**
* Timeline: lancer la mesure
*/
public function timeStart() {
self::$time_line_laststamp = microtime(true);
self::$time_line_firststamp = self::$time_line_laststamp;
self::$time_line[] = array(0, 0, 'start');
}
 
/**
* Timeline: ajouter un point d'arrêt
*/
public function timeAddPoint($msg = '') {
$t_cur = microtime(true);
$t_elapse_last = $t_cur - self::$time_line_laststamp;
$t_elapse_first = $t_cur - self::$time_line_firststamp;
 
 
self::$time_line_laststamp = $t_cur;
self::$time_line[] = array($t_elapse_first, $t_elapse_last, $msg);
}
 
/**
* Timeline: arrêter la mesure
*/
public function timeStop() {
$t_cur = microtime(true);
$t_elapse_last = $t_cur - self::$time_line_laststamp;
$t_elapse_first = $t_cur - self::$time_line_firststamp;
 
 
self::$time_line_laststamp = $t_cur;
self::$time_line[] = array($t_elapse_first, $t_elapse_last, 'end');
}
 
/**
* Cumul: débuter l'addition du temps d'execution
* @param type $msg
*/
public function time_mesure_start($msg = '') {
if (!empty($msg)) {
$id = $msg;
} else {
$id = 'dummy';
}
self::$time_pool[$id] = array('start', microtime(true), $msg);
}
 
/**
* Cumul: arrêter l'addition du temps d'execution
* @param type $msg
*/
public function time_mesure_end($msg = '') {
if (!empty($msg)) {
$id = $msg;
} else {
$id = 'dummy';
}
//Time Elapse
$time_elapse = -1;
if (isset(self::$time_pool[$id]) && self::$time_pool[$id][0] == 'start') {
$time_elapse = microtime(true) - self::$time_pool[$id][1];
}
//Concat
if ($time_elapse > -1) {
$time_count = 0;
if (isset(self::$time_periods[$msg])) {
$time_count = self::$time_periods[$msg];
}
self::$time_periods[$msg] = $time_count + $time_elapse;
}
}
 
/**
* Timeline: visualiser le résultat sous forme de string
* @return string
*/
public function getTimeLineString() {
$buf = '';
if (count(self::$time_line) > 0) {
$buf.=str_pad('from start', 12) . "t" . str_pad('from last', 12) . "t" . 'tag' . "n";
foreach (self::$time_line as $row) {
$buf.=number_format($row[0], 10, ',', ' ') . "t";
$buf.=number_format($row[1], 10, ',', ' ') . "t";
$buf.=$row[2] . "n";
}
}
return $buf;
}
 
/**
* Cumul: visualiser le résultat sous forme de string
* @return string
*/
public function getTimeMesureString() {
$buf = '';
if (count(self::$time_periods) > 0) {
$maxlen = 0;
foreach (self::$time_periods as $key => $val) {
$maxlen = max($maxlen, strlen($key));
}
$maxlen+=2;
 
$buf.=str_pad('tag', $maxlen) . "t" . 'time' . "n";
foreach (self::$time_periods as $key => $val) {
$buf.=str_pad($key, $maxlen) . "t";
$buf.=number_format($val, 10, ',', ' ') . "t" . "n";
}
}
return $buf;
}
}
?>

Donc pour améliorer les performances des scripts PHP et trouver les bugs, la classe cumule les temps d’exécution de certaines taches et affiche le timeline de l'ensemble de l’exécution.

Cas pratique de debuggage

La classe Debug_Logger a été crée pour trouver la lenteur dans mon application. Codeur de la première heure, je n'utilise aucun framework ou aide dans le genre. Ainsi en premier lieu, j'ai placé des microtime(true) pour mesurer les temps d’exécution en pensant que les accès aux bases de données ralentissaient le script PHP.
Voici un exemple de script que l'on souhaite corriger et mesures les performances.

<?php
//mon script buggy et trop lent
//Démarrer le timeline
Debug_Logger::getInstance()->timeStart();
 
//Accès au DB
Debug_Logger::getInstance()->timeAddPoint('avant les selections MySql');
for($i=0;$i<10;$i++) {
Debug_Logger::getInstance()->time_mesure_start('Select_Mysql');
//SELECT * FROM MATABLE WHERE ....
//simulation de la requete avec 100 ms
usleep(100000);
Debug_Logger::getInstance()->time_mesure_end('Select_Mysql');
}
Debug_Logger::getInstance()->timeAddPoint('fin des selections MySql');
 
//Scrapper internet
Debug_Logger::getInstance()->timeAddPoint('avant le chargement des url');
for($i=0;$i<10;$i++) {
Debug_Logger::getInstance()->time_mesure_start('file_get_contents');
//file_get_contents('http://www....')
//simulation de la requete avec 500 ms
usleep(500000);
Debug_Logger::getInstance()->time_mesure_end('file_get_contents');
}
Debug_Logger::getInstance()->timeAddPoint('après le chargement des url');
 
//Insert DB
Debug_Logger::getInstance()->timeAddPoint('avant les insertions MySql');
for($i=0;$i<10;$i++) {
Debug_Logger::getInstance()->time_mesure_start('Insert_Mysql');
//INSERT INTO MATABLE (....
//simulation de la requete avec 200 ms
usleep(200000);
Debug_Logger::getInstance()->time_mesure_end('Insert_Mysql');
}
Debug_Logger::getInstance()->timeAddPoint('fin des insertions MySql');
 
//Fin du timeline
Debug_Logger::getInstance()->timeStop();
 
//Afficher les mesures
echo 'TimeLine'."n".Debug_Logger::getInstance()->getTimeLineString();
echo 'Cumul'."n".Debug_Logger::getInstance()->getTimeMesureString();
?>

L'exemple de script PHP lent utilise des temps de pause pour simuler les temps d'accès ou de chargement. Affichons les résultats pour mesurer les performances du script (benchmark) tout au long de son exécution et le cumul des temps de certaines tâches.

TimeLine
from start from last tag
0,0000000000 0,0000000000 start
0,0000059605 0,0000059605 avant les selections MySql
1,0008039474 1,0007979870 fin des selections MySql
1,0008070469 0,0000030994 avant le chargement d'url
6,0016081333 5,0008010864 après le chargement d'url
6,0016131401 0,0000050068 avant les insertions MySql
8,0024199486 2,0008068085 fin des insertions MySql
8,0024249554 0,0000050068 end

Cumul
tag time
Select_Mysql 1,0007259846
file_get_contents 5,0007319450
Insert_Mysql 2,0007359982

Interprétation:
Timeline: du début du script jusqu'au chargement des url, le script a nécessité 1,008 sec. Ensuite la période entre 1,0008070469 sec et 6,0016081333 sec est utilisé par le chargement des URL (5,0008010864 / après le chargement d'url).

Cumul: les accès à la base de données (Select_Mysql+Insert_Mysql) prennent environ 3 secondes alors que le chargement des url (file_get_contents) nécessite plus de 5 secondes.

En conclusion, pour améliorer les performances du scripts, la mise en chargement parallèle des url permettra d'avoir le meilleur gain en terme de temps d’exécution.

Note: la classe Debug_Logger peut être utilisé dans un contexte statique et dans n'importe quel script PHP contenu dans votre application.
Pour la petite histoire, la classe Debug_Logger a été écrite pour chercher un fichu bug qui ralentissait mon application de 500 ms. Et .... grâce aux mesures de performances, le bug a été corrigé, il s'agissait d'une routine de comparaison de string en UTF8 non optimisée !

Mesurer les performances et deboguer un script php

Rechercher les lenteurs d'un script PHP

Cas pratique de debuggage

Ajouter un commentaire

A lire aussi