Le 27 juillet 2010 16:45, Olivier Bonvalet frsag.list@daevel.fr a écrit :

Bonjour,

Le 27/07/2010 16:32, frantishrek a écrit :

...

J'aimerais avoir votre retour d'expérience sur l'analyse des logs PHP.

Je cherche une solution qui :  - me permette d'être alertée des erreurs des scripts PHP  - des fréquences des différentes erreurs  - si possible avec la pile d'exécution (backtrace)  - si possible avec l'URL de la page incriminée  - si possible avec les variables de session, post, get, ...

Ormis pour la fréquence, le reste est faisable en surchargeant le gestionnaire d'erreur de PHP. A faire coté script donc.

Merci pour la réponse. Oui, effectivement (via un set_error_handler()), mais c'est la fréquence qui m'intéresse le plus. Exemple : Si j'ai un script qui plante et que j'ai 300 internautes qui "exécutent" ce script, mon fichier de log va contenir 300 fois la même erreur. Je souhaiterais avoir, si possible, des erreurs consolidés.

François

Pour pouvoir les consolider, il faut les stocker quelque part... dans une base SQLITE par exemple. Néanmoins le principe reste le même : un gestionnaire d'erreur maison, à placer dans auto_prepend_file.

Par contre certains softs/frameworks surchargent déjà le gestionnaire d'erreur (ZendFramework par exemple).

Oui, cela pourrait être la solution. Mais j'aimerais si possible trouver une solution un peu packagée, maintenue, fiable,... mais je partirais là-dessus si je ne trouve rien d'autres. Quelqu'un qui gère une grosse infra pourrait-il faire un retour d'expérience sur la solution mise en œuvre ? D'autres idées ?

Merci,

Le 27/07/2010 18:01, Xavier Garreau a écrit :

frantishrek a écrit :

...

D'autres idées ?

Logger les erreurs PHP dans syslog et avoir un script en cron à base de awk, sort, uniq, ... Ou perl s'il reste de l'efferalgan :D

C'est ce que je fais... en plus de la surcharge du gestionnaire d'erreur de PHP, seul à permettre de relié une erreur à un "contexte" (URL, stack, session, post, login, etc). En tous cas je n'ai rien trouvé de mieux que de le faire moi même.

Mais je suis pas assez gros ;)

Olivier

Par contre, éviter xdebug en prod...

Pour du profilage au fil de l'eau, il y xhprof (à utiliser en échantillonnage : pas sur tous les serveurs, et pas sur toutes les requêtes).

Ca permet de faire des agrégats journaliers, des comparaisons d'un jour sur l'autre/d'une semaine sur l'autre (avec un peu de code PHP, mais pas grand chose)...

JFB

Le 27 juil. 2010 à 21:28, Xavier Garreau a écrit :

Olivier Bonvalet a écrit :

...

Le 27/07/2010 18:01, Xavier Garreau a écrit :

...

frantishrek a écrit :

...

D'autres idées ?

Logger les erreurs PHP dans syslog et avoir un script en cron à base de awk, sort, uniq, ... Ou perl s'il reste de l'efferalgan :D

C'est ce que je fais... en plus de la surcharge du gestionnaire d'erreur de PHP, seul à permettre de relié une erreur à un "contexte" (URL, stack, session, post, login, etc). En tous cas je n'ai rien trouvé de mieux que de le faire moi même. Mais je suis pas assez gros ;)

Il faudrait voir si xdebug n'est pas capable de dumper la stack trace dans un fichier de log. Ca doit être possible sans gros effort. Et si on est sur un serveur de dév, il permet même le profiling :)

Xavier Garreau xavier@xgarreau.org http://www.xgarreau.org/

---

FRsaG mailing list FRsaG@frsag.org http://www.frsag.org/mailman/listinfo/frsag

Le 27 juil. 2010 à 23:18, frantishrek a écrit :

J'ai vu passé des news sur xhprof mais je ne l'ai pas testé. D'après ce que j'en ai vu, cela semble être un xdebug (développé par facebook) un peu mieux foutu dont les traces sont un peu moins verbeuses. Ca s'installe sur un serveur de prod' ? Quelqu'un a testé ?

Ca tourne sur un de mes serveurs de prod (plateforme d'une petite cinquantaine de serveurs).

1 frontal (sur 20) a l'extension loadée, et le code déclenche xhprof entre une fois toutes les 1000 requêtes (mon objectif est d'avoir une trace toutes les 10 à 30 secondes).

Un script tourne toutes les nuits pour aggréger les données de la journée, et générer un rapport sur le top du jour (cpu, mémoire), et faire un delta avec J-1 et J-7. C'est *très* rustique par rapport à ce que Facebook fait (ils ont couplé ça avec une vraie interface de reporting, avec de beaux graphes, et un mécanisme d'alerting).

Globalement :

- oui ça a un léger impact sur la charge du serveur, (j'allais mettre "impact sensible", mais en reprenant mes courbes cpu/mémoire/load/requêtes http, je m'aperçois que l'impact est inférieur à 10% en mode nominal, donc pas si important que ça - à revalider avec une charge importante),

- pour ce qui est du temps de génération des pages, aucun impact n'apparait sur mes graphes de prod ; de toutes façons, le temps de génération dépend dans notre cas essentiellement de la latence des accès memcache - pour une appli standard faisant des accès externes (webservice ou base ou memcache), ce sera pareil,

- ça donne un résultat tellement utile que ce serait dommage de s'en priver

Le profilage en dev/recette ne remplacera jamais un profilage au fil de l'eau (et inversement), parce que c'est le meilleur moyen d'avoir un profilage extensif, c'est le meilleur moyen d'avoir du "profilage de non régression", et parce que l'immense majorité des sites web n'ont pas le temps/les hommes/le matériel pour faire une recette extensive dans des conditions identiques à la prod à chaque livraison de code. (on va mettre de côté les gros sites de eCommerce qui ont des besoins et des moyens différents du commun des mortels).

C'est comme pour le monitoring : mieux un serveur très bien monitoré, même si ça le fait péter à 90 de charge au lieu de 100, parce que tu peux identifier et corriger proprement les goulets d'étranglement longtemps avant que ça pète, plutôt que de paniquer le jour où ça pète et bricoler une verrue en panique pour que ça passe.

Si des gens sont intéressés, je peux filer mon code.

Le 28 juil. 2010 à 01:11, Pierre-Henry Muller a écrit :

mode admin sys qui parle : rien en production ne doit donner la structure de ton site (archi, code, path, ...) donc pas de xdebug ou xhprof

Je comprends ton inquiétude pour ce qui a une chance de s'afficher. Maintenant, le danger pour moi est plus grand avec un PHP "bare" qui est paramétré pour afficher les erreurs qu'avec un PHP + xdebug qui est paramétré pour ne rien afficher, mais logguer.

(Ceci étant dit, c'est une mauvaise idée d'avoir xdebug en prod : cela n'apporte pas plus de visibilité sur les bugs que ce qu'on peut avoir avec un gestionnaire d'erreur bien foutu; côté profilage, xhprof est mieux adapté, et côté debug/code coverage, qui a envie de faire tourner ça sur un serveur de prod ?).

Pour ce qui est de xhprof, cela ne change rien au niveau des erreurs générées, cela ne rend rien plus ou moins verbeux, ça rajoute juste quelques fonctions php pour déclencher le profilage et récupérer les données. Pourquoi donc refuser "par principe" ?

JFB

Le 28 juil. 2010 à 15:10, Pierre-Henry Muller a écrit :

Oui je suis sans doute allé un peu vite dans l'idée, effectivement on peut tout rediriger dans un log. Mais la consommation mémoire des deux modules est conséquente, pour un ordre d'idée avec un framework perso (les symfony et autres consomment bien trop) en prod je consomme 900Ko en moyenne par requête, pour un temps de calcul de 0.035 sec avec requêtes sql, memcache et mogilefs, dès que je charge xdebug je monte à 2,5Mo de mémoire et un temps moyen de 0,45 sec par requête.

Tu as comparé avec xhprof ? Sur ma plateforme, je n'ai vraiment pas les mêmes impacts...

JFB

Le 28 juillet 2010 09:39, JF Bustarret jf@bustarret.com a écrit :

[...] Si des gens sont intéressés, je peux filer mon code.

Merci pour le retour d'expérience. Je suis intéressé par ton code même si aujourd'hui je n'utilise pas xhprof, ton mail me donne envie de m'y intéresser.

bonne journée, François

Vu que ça intéresse du monde, et même si on attend la zone floue entre plateforme et appli (ceci étant dit, je suis partant pour un grand débat sur la séparation des pouvoirs entre système et dev), voilà la version "rustique" de la chose :

La config PHP :

[xhprof] extension=xhprof.so xhprof.output_dir=[répertoire temporaire où sont stockés les traces]

En tout début de code ou dans un fichier à part, chargé en auto_prepend_file (attention, tout ce qui est exécuté avant n'est pas profilé) - je ne trace que ce qui est en HTTP (d'où le isset($_SERVER...), et je ne trace pas les fonctions PHP (XHPROF_FLAGS_NO_BUILTINS) pour ne pas trop surcharger les traces :

if (function_exists('xhprof_enable') && isset($_SERVER['HTTP_HOST']) && mt_rand(1, XXX) == 1) { function save_xhprof_data() { $xhprof_data = xhprof_disable();

include_once CODE_BASE . "lib/xhprof/utils/xhprof_lib.php"; include_once CODE_BASE . "lib/xhprof/utils/xhprof_runs.php"; $xhprof_runs = new XHProfRuns_Default(); $run_id = $xhprof_runs->save_run($xhprof_data, "xhprof_data"); } xhprof_enable(XHPROF_FLAGS_NO_BUILTINS + XHPROF_FLAGS_MEMORY); register_shutdown_function('save_xhprof_data'); }

NB : - les libs xhprof_xxx sont founies avec xhprof, remplacer le CODE_BASE par l'endroit où sont placées ces libs. - remplacer le XXX du mt_rand par la valeur qui vous permet d'avoir quelques traces par minute

Pour l'analyse :

xhprof_aggregate.php - croner xhprof_aggregate.php toutes les nuits pour consolider les données de la veille - lancer xhprof_aggregate.php simul pour simuler l'exécution et afficher le rapport en cours

Ca sort tout sur la sortie standard, ça peut donc se rediriger dans un log, ou générer un mail, comme toute cron...

Je vous laisse vous inspirer de tout ça pour faire quelque chose de plus industriel (fusion de logs de plusieurs serveurs, stockage des données en base, etc.)

#!/usr/bin/php <?php

define('SEUIL_DELTA', 20); define('NB_TOP', 20);

$output_dir = ini_get("xhprof.output_dir");

$dir = new DirectoryIterator($output_dir);

include_once CODE_BASE . "lib/xhprof/utils/xhprof_lib.php"; include_once CODE_BASE . "lib/xhprof/utils/xhprof_runs.php"; include_once CODE_BASE . "lib/xhprof/display/xhprof.php";

$simul = (count($argv) > 1 && $argv[1] == "simul");

// On prend tous les fichiers de run présents dans le répertoire // qu'on va ensuite agréger

$aggregatedfile = $output_dir."/".date("Ymd").".aggregated"; if (!$simul && file_exists($aggregatedfile)) { $aggregated = unserialize(file_get_contents($aggregatedfile)); $files = array(); } else { foreach ($dir as $file) { if ($file->isFile() && preg_match('/([a-z0-9]+).xhprof_data/', $file->getBasename(), $matches)) { $run_ids[] = $matches[1]; $files[] = $file->getPathname(); } } if (count($run_ids) == 0) { die("Pas de run à analyser"); }

$xhprof_runs = new XHProfRuns_Default(); $aggregated = xhprof_aggregate_runs($xhprof_runs, $run_ids, array(), "xhprof_data"); if (!$simul) { file_put_contents($aggregatedfile, serialize($aggregated)); } }

$computed = xhprof_compute_flat_info($aggregated['raw'], $total); //print_r($computed);

// Calcul des tops

function displayTop($computed, $key, $scale = 1000) { $slice = array_slice($computed, 0, NB_TOP); $max = null; foreach($slice as $call => $data) { $val = round($data[$key]/$scale); if ($max == null) $max = $val; printf("%s : %d (count %d / avg %.2f / %d %%)\n", $call, $val, $data['ct'], $val/$data['ct'], 100*$val/$max); } } // Top par wall-time (self) function compareWT($a, $b) { global $computed; return $computed[$a]['excl_wt'] < $computed[$b]['excl_wt']; } uksort($computed, "compareWT"); print "\nTop 10 (temps self/msec)\n"; displayTop($computed, 'excl_wt');

// Top par wall-time (total) function compareWT2($a, $b) { global $computed; return $computed[$a]['wt'] < $computed[$b]['wt']; } uksort($computed, "compareWT2"); print "\nTop 10 (temps incl/msec)\n"; displayTop($computed, 'wt');

// Top par mémoire utilisée (self) function compareMU($a, $b) { global $computed; return $computed[$a]['excl_mu'] < $computed[$b]['excl_mu']; } uksort($computed, "compareMU"); print "\nTop 10 (memory self/Mo)\n"; displayTop($computed, 'excl_mu', 1024*1024);

// Calcul des diff par rapport à hier // On ne prend que le top des entrées

function delta($before, $today_pruned) { global $computed;

$delta = false; $computed = xhprof_compute_flat_info($before['raw'], $total); uksort($computed, "compareWT"); $before_pruned = array_slice($computed, 0, NB_TOP); //$before_pruned = xhprof_compute_flat_info(xhprof_prune_run($before['raw'], SEUIL_DELTA), $total); foreach ($today_pruned as $fn => $data) { if (!isset($before_pruned[$fn])) { //print "Apparition : $fn (temps incl ".$data['wt']."/self ".$data['excl_wt'].")\n"; $val = round($data['excl_wt']/1000); printf("Apparition de %s : self %d (count %d / avg %.2f)\n", $fn, $val, $data['ct'], $val/$data['ct']); $delta = true; } else { $beforedata = $before_pruned[$fn]; //print "Déjà présent : $fn (temps incl ".$data['wt']."/self ".$data['excl_wt'].")\n"; $val = round($data['excl_wt']/1000); $beforeval = round($beforedata['excl_wt']/1000); printf("Déjà présent %s : self %d (count %d / avg %.2f vs %.2f)\n", $fn, $val, $data['ct'], $val/$data['ct'], $beforeval/$beforedata['ct']); } } foreach ($before_pruned as $fn => $data) { if (!isset($today_pruned[$fn])) { //print "Disparition : $fn (temps incl ".$data['wt']."/self ".$data['excl_wt'].")\n"; $val = round($data['excl_wt']/1000); printf("Disparition de %s : self %d (count %d / avg %.2f)\n", $fn, $val, $data['ct'], $val/$data['ct']); $delta = true; } } return $delta; }

uksort($computed, "compareWT"); $today_pruned = array_slice($computed, 0, NB_TOP);

$yesterdayfile = $output_dir."/".date("Ymd", strtotime("-1 day")).".aggregated"; if (file_exists($yesterdayfile)) { print "\nDelta par rapport à hier :\n"; $before = unserialize(file_get_contents($yesterdayfile)); delta($before, $today_pruned); }

$lastweekfile = $output_dir."/".date("Ymd", strtotime("-1 week")).".aggregated"; if (file_exists($lastweekfile)) { print "\nDelta par rapport à la semaine dernière :\n"; $before = unserialize(file_get_contents($lastweekfile)); delta($before, $today_pruned); }

if (!$simul) { foreach($files as $path) { unlink($path); } }

NB: - il est possible qu'il reste des dépendances par rapport au reste de l'appli (même si un nettoyage a été fait), et que ça ne demande donc des adaptations pour marcher chez vous - le pourcentage affiché est par rapport à la fonction qui consomme le plus, pas par rapport au temps global d'exécution (qu'on ne connait pas), histoire d'avoir des ordres de comparaison - si vous n'arrivez pas à faire marcher le code, c'est que c'était une mauvaise idée d'essayer

JFB

frantishrek a écrit :

Le 27 juillet 2010 21:28, Xavier Garreau xavier@xgarreau.org a écrit :

...

Il faudrait voir si xdebug n'est pas capable de dumper la stack trace dans un fichier de log. Ca doit être possible sans gros effort. Et si on est sur un serveur de dév, il permet même le profiling :)

xdebug est effectivement capable de dumper la stack trace dans un fichier de log mais je ne suis pas certain que cela soit une bonne chose de déployer xdebug sur des serveurs de prod ;-) et ça ne règle pas mon problème d'agrégat ;-)

Je suis même certain du contraire :) à mon sens il y a 2 problématiques. Trouver les erreurs récurrentes sur le serveur de prod (solution syslog+script) et les analyser/résoudre sur le serveur de dév (solution xdebug+profiling).

<mauvaise foi>En même temps, pourquoi y aurait-il des erreurs en prod, puisque ça a été prodé :D</mauvaise foi>