Publié le 23/06/2016
Auteur fobec
Réseaux sociaux
0 partages
0 tweets
0 plus
0 commentaires

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 !

Ajouter un commentaire

Les champs marqués d'un * sont obligatoires, les adresses emails se sont pas publiées.

A lire aussi

Réseaux sociaux
Présentation de l'article
Catégorie
php5 - class
Mise a jour
23/06/2016
Visualisation
vu 3198 fois
Public
Internaute
Auteur de la publication
Fobec
Admin
Auteur de 261 articles
|BIO_PSEUDO|
Commentaires récents

Publié par gilles dans logiciel

Bonjour,

j'utilise quotidiennement votre excellent logiciel complet et ergonomique.

Mais depuis quelques jours j'ai un probleme il recherche indefiniment resolution du nom de l'hote.

Publié par Diviciakos dans CMS

Merci ! Bonne continuation

Publié par Fobec dans CMS

Norton emet une alerte de type 'Suspicious.Cloud', hasard de compilation ou menace serieuse ? Faites attention en installant le logiciel.<br>Merci JM de l'avoir signaler.

Publié par mfranca dans CMS

Bonjour, Excellent outil pour moi, très interessant pour mes recherches en amateur...
Merci pour cette création Olubil
Ciao ciao

Publié par nico dans java

Petite erreur constate.
Apparemment il faut remplacer :
&mailTo = &?body=Envoyer un email avec Java
par &mailTo = < et commercial sans '<' et '>' &body=Envoyer un email avec Java