Publié le 23/06/2016
Auteur fobec
Réseaux sociaux
0 partages
0 tweets
1 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 799 fois
Public
Internaute
Auteur de la publication
Fobec
Admin
Auteur de 261 articles
|BIO_PSEUDO|
Commentaires récents

Publié par Daxentuut dans java

Avec les imports c'est mieux :

import java.awt.AWTException
import java.awt.Robot
import java.awt.event.KeyEvent
import java.io.IOException
import java.util.logging.Level
import...

Publié par jmc dans CMS

Autre lien de chargement : http://www.fobec.com/protec/logiciels2/encadre.php3?id_log=217&cat=VBureautique

Publié par mohinfo dans CMS

je vous demande un mini projet delphi pour gérer la base de donnée

Publié par zozo dans logiciel

comment ca marche??????????

Publié par Roy2014 dans tuto

Bonjour et merci pour ce tuto interessant. Je pense que tout le monde souffre avec 1and1 du fait que l'on puisse pas gziper directement via le htaccess!!
j'aurais une petite question:
tu dis a p...