Monitorer le temps de création des pages PHP par le serveur avec Munin

Ce qui est bien quand on utilise un framework comme Symfony pour développer, c'est de connaitre le temps d'execution d'une page sur le serveur en regardant la debug toolbar. Cela donne une bonne indication si la page est lente et donc couteuse en temps machine. Mais que se passe-t-il une fois que le code est sur le serveur de production. Est ce que les pages sont toujours aussi rapide? Est ce constant? On peut utiliser AB (apache bench) ou Firebug pour faire des tests, mais cela ne donne qu'une valeur à un instant t. Dans tous les cas (serveur surchargé ou pas) ce type de test ne permet pas d'avoir une lecture de la réalité dans le temps, ni de croiser les données temps de génération/nombre de visite ou page.

J'ai donc dévelopé un plugin Munin pour monitorer le temps d'exécution des pages PHP.

1. Connaitre le temps d'exécution des pages

Depuis la version 1.3, le serveur web Apache inclus en standard le mode mod_log_config qui permet plus de flexibilité dans la création des logs. Il est possible d'ajouter pour chaque ligne de log le temps que le seveur à pris pour générer la réponse avant de l'envoyer.Je trouve cette solution beaucoup plus simple que de devoir modifier le code PHP des pages pour y ajouter des appels à microtime().

a. Création du format de log

Je commence par ajouter un nouveau format de log à la configuration d'Apache. Ce format sera nommé et ainsi je pourrais facilement l'utiliser et l'activer suivant les cas. J'édite donc le fichier apache2.conf

 
> vim /etc/apache2/apache2.conf

Une fois que j'ai trouvé les lignes contenant la description des logs, lignes commencant par LogFormat, j'ajoute la ligne suivante à la liste.

 
LogFormat "%h %l %u %T/%D %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\"" time_combined

Je n'ai fait que dupliquer la déclaration du log combined en ajoutant %T/%D. %T indique le temps en seconde et %D le temps en microseconde. Pourquoi cette redondance? Car il est plus simple quand on chercher "à la main" de trouver  les pages qui prennent plus d'une seconde plutot que les pages qui prennent plus de 1000000 microseconde.

b. Utilisation du nouveau format de log

Il ne me reste plus qu'a choisir sur quel vhost je veux utiliser ce format. Identifier la ligne CustomLog dans le vhost et remplacer le format du log précédent par le nouveau.

 
> vim /etc/apache2/site-available/blog

 
# je remplace cette ligne:
CustomLog /var/logs/mon-code/access.log combined
 
# par celle ci
CustomLog /var/logs/mon-code/access.log time_combined

Il faut redémarrer apache pour prendre en compte la nouvelle configuration

 
> /etc/init.d/apache2 force-reload

Après quelques secondes en faisant un tail sur les logs on devrait voir le résultat.

 
> tail -f /var/logs/mon-code/access.log
 
94.23.63.96 - - 0/199435 [03/Apr/2012:14:05:08 +0200] "GET / HTTP/1.0" 200 20731 "-" "Wget/1.12 (linux-gnu)"
94.23.63.96 - - 0/1006 [03/Apr/2012:14:05:08 +0200] "GET /robots.txt HTTP/1.0" 200 341 "-" "Wget/1.12 (linux-gnu)"
94.23.63.96 - - 0/827 [03/Apr/2012:14:05:08 +0200] "GET /css/main_1.1.css HTTP/1.0" 200 11819 "http://www.mon-code.net/" "Wget/1.12 (linux-gnu)"
 

Idéalement le serveur doit répondre sous la seconde, le premier chiffre devrait donc toujours être 0 suivis du temps en microseconde. Dans l'exemple ci dessus on vois qu' il a fallu 199ms au serveur pour générer la homepage et aux alentours de la miliseconde pour les fichiers statiques, ce qui est logique apache n'ayant rien de spécial à faire avec ce type de fichier.

2. Monitorer les temps d'exécution

Comme j'ai fait pour les logs d'erreur, j'ai créer un plugin pour Munin qui me permet d'obtenir des courbes des temps de génération des pages. Le but du plugin est d'obtenir 3 courbes, une réprésentant le temps de le plus long, une autre le temps le plus court et évidemment la dernière la moyenne.

Munin se lance toutes les 5 minutes dans sa configuration originale, idéalement il faudrait calculer les valeurs sur cet interval de 5 minutes. Or je n'ai pas assez de visites pour obtenir des données intéréssantes, le gros des visites sur le blog se fait entre 10h et 19h et le nombre de page vue n'est pas suffisant pour avoir des données à chaque exécution de Munin. J'ai donc décidé de me baser sur les X dernières pages qui sont dans les logs. Je fais varier X en fonction de l'évolution des visites du blog.
De plus, il n'est pas intéréssant dans mon cas d'intégrer le temps des fichiers statiques, pour le blog, ils ne font pas appelle à PHP et ils sont tellement nombreux et peu gourmand en temps machine que les courbes basse et moyenne ne serait plus réaliste.

a. Plugin Munin

Voici le code du plugin à mettre dans: /usr/share/munin/plugins/apache_generate_time

 
#!/bin/sh
#
# Plugin to monitor execution time of PHP with access.log from apache server.
# Need to use apache module mod_log_config and have  set logformat like this:
# LogFormat "%h %l %u %T/%D %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\"" time_combined
#
# Require read permitions for $LOG
#  (set in /etc/munin/plugin-conf.d/munin-node on debian)
# On busy servers you can change value type to COUNTER and set min to 0 to avoid minus peaks at logrotate
#
# $Log$
# Revision 0.1  2012/04/05 12:00:00  Ulrich Lusseau
# Initial revision
#
# Parameters:
#
#       config   (required)
#       autoconf (optional - used by munin-config)
#
# Magick markers (optional):
#%# family=auto
#%# capabilities=autoconf
#
# config example for /etc/munin/plugin-conf.d/munin-node
#[apache_generate_time]
#user root
#env.logfile /home/newsite/logs/access.log
#env.sitename mon-code
#env.nbrpage 10
#
 
LOG=${logfile:-/var/log/apache2/access.log}
NAME=${sitename:undefined}
NBRPAGE=${nbrpage}
 
 
if [ "$1" = "autoconf" ]; then
        if [ -r "$LOG" ]; then
                echo yes
                exit 0
        else
                echo no
                exit 1
        fi
fi
 
if [ "$1" = "config" ]; then
 
        echo 'graph_title Time to generate PHP page ' $NAME 'v2'
        echo 'graph_args --base 1000 -l 0'
        echo 'graph_vlabel Time in microsecond'
 
        echo "graph_category PHP"
        echo "graph_info This graph shows load time in microseconds of $target"
        echo "minloadtime.label Min time"
        echo "minloadtime.info Min time"
        echo "avgloadtime.label Avg time"
        echo "avgloadtime.info Avg time"
        echo "maxloadtime.label Max time"
        echo "maxloadtime.info Max time"
 
        exit 0
fi
 
 awk '($4 ~ /[0-9]+\/[0-9]+/ && $8 !~ /\.(jpg|JPG|jpeg|JPEG|gif|GIF|png|PNG|txt|TXT|css|CSS|js|JS|zip|ZIP|bmp|BMP)$/)' $LOG     | sed -e :a -e '$q;N;'$NBRPAGE',$D;ba' | awk '{print $4}' | awk -F\/ ' MIN=="" || $2 < MIN {MIN=$2}  MAX=="" || $2 > MAX {MAX=$2}  {SUM += $2} END {print  "minloadtime.value ",MIN/1000,"\navgloadtime.value ",SUM/(NR*1000),"\nmaxloadtime.value ",MAX/1000}'
 
 

b. Configuration de Munin

L'utilisation du plugin est assez facile, il faut faire un lien symbolique du plugin dans le dossier /etc/munin/plugins:

 
> ln -s /usr/share/munin/plugins/apache_generate_time apache_generate_time

Puis éditer la configuration de munin (/etc/munin/plugin-conf.d/munin-node)

 
[apache_generate_time]
user root
env.logfile /home/blog/logs/access.log
env.sitename Blog
env.nbrpage 50

Le paramêtre nbrpage est important, il s'agit du nombre de page que munin va utiliser à chaque exécution pour calculer les courbes, ce paramètre est à éditer suivant l'audience de vos sites.
Il ne reste plus qu'a redémarer munin.

Voici le type de graphique que vous devriez obtenir:

EDIT: le plugin est disponible dans le dépot contrib-plugin de Munin sur github.