XHTML.net

1. Home
2. PHP: Hypertext Preprocessor
3. Pluf - Framework en PHP5

Utiliser assert pour faire du log à haute performance en PHP

The 2009-10-30 at 14:30 by Loïc d'Anterroches filed under Pluf - Framework en PHP5.

Imaginez que vous vouliez tracer des informations dans l’exécution de votre application web, en gros, logger des informations, vous trouverez très facilement des class PHP vous permettant d’ajouter cela dans votre code :

// mon code qui fait quelque chose
$logger->log('Mon information');
Mon_Logger::debug($variable);
// la suite du code etc...

Dans le premier cas vous loggez via une méthode d’un objet, dans le suivant via une méthode statique, cela pourrait aussi être via un code du genre Factory::get('logger')->log('message').

Cette approche a malheureusement 2 problèmes :

1. une perte de performance du code en production quand on ne veut pas logger ;
2. le manque de contexte au niveau du log, il faut souvent alors ajouter des informations dans le message pour savoir d’où vient le message.

La perte de performance peut être partiellement levée par l’utilisation de l’injection de dépendances et charger ainsi un objet de log stupide, qui ne fera rien à son appel. Mais on garde alors un triple coût au niveau des performances :

1. coût de l’injection de dépendance pour charger le bon logger ;
2. coût de la génération du message pour ensuite ne rien en faire ;
3. coût de l’appel à une méthode statique PHP utilisateur, qui ne fait rien.

Dans Pluf, je n’ai pas proposé de méthode particulière et je laisse les gens utiliser le système de leur choix car je n’avais pas trouvé de méthode qui limite vraiment la perte de performance en production, jusqu’à hier.

PHP dispose des assertions, les assertions permettent d’évaluer un morceau de code et d’agir si le résultat est false. Je vous laisse lire la documentation, c’est rapide.

Les côtés très intéressants des assertions sont :

1. on peut les activer et les désactiver dynamiquement ;
2. si on passe une chaîne en entrée elle est évaluée comme du code dans le contexte local ;
3. on peut récupérer le nom du fichier et la ligne où l’exception a été exécutée via un callback.

Conclusion, vous pouvez mettre votre code à logger dans votre chaîne pour votre exception et si votre logger retourne false votre callback va se faire appeler. Si dans votre logger vous ne faites que stocker temporairement votre message, vous pouvez dans le callback reconstituer l’ensemble des informations et vraiment stocker dans votre fichier de log ou ailleurs.

Voici un bout de code pour illustrer :

<?php
function log_assert($file, $line, $code)
{
    $GLOBALS['log'][] = array(
        microtime(true),
        $file, $line, $code,
        isset($GLOBALS['last_assert_res']) ? $GLOBALS['last_assert_res'] : ''
                              );
    $GLOBALS['last_assert_res'] = null;
}

function logger($text)
{
    $GLOBALS['last_assert_res'] = $text;
    // false va forcer l'appel à log_assert
    return false; 
}

// Active les assert en les rendant silencieuses
assert_options(ASSERT_ACTIVE, 1); 
assert_options(ASSERT_WARNING, 0);
assert_options(ASSERT_QUIET_EVAL, 1);
assert_options(ASSERT_CALLBACK, 'log_assert');

$assert = array(1, 0);
$n = 10000;
foreach ($assert as $active) {
    $GLOBALS['log'] = array();
    assert_options(ASSERT_ACTIVE, $active); 
    $start = microtime(true);
    for ($i=0;$i<$n;$i++) {
        assert('logger($i.' is an integer')');
    }
    $time = microtime(true) - $start;
    print "Assert active: $active\n";
    print "Elapsed time: $time\n";
    print "Per call: ".($time/$n)."\n";
    print "Log size: ".count($GLOBALS['log'])."\n\n";
    if (count($GLOBALS['log'])) {
        var_dump($GLOBALS['log'][0]);
        print "\n\n";
    }
}

Cela vous donnera un résultat du genre :

$ php test.php 
Assert active: 1
Elapsed time: 0.403494119644
Per call: 4.03494119644E-5
Log size: 10000

array(5) {
  [0]=>
  float(1256912192.17)
  [1]=>
  string(36) "/home/loa/Projects/pluf/tmp/test.php"
  [2]=>
  int(32)
  [3]=>
  string(27) "logger($i.' is an integer')"
  [4]=>
  string(15) "0 is an integer"
}


Assert active: 0
Elapsed time: 0.03799700737
Per call: 3.799700737E-6
Log size: 0

En gros, votre logger est 10x plus rapide en production si il ne logge rien. Le assert('code') coûte autant que le coût d’un appel de la plus simple des fonctions PHP comme is_numeric ou autre, totalement négligeable en mode production. Si on compare avec l’appel à une méthode statique utilisateur qui ne fait rien, le code qui logge ne coûte que 30% de plus ! La fonction assert est donc très optimisée et on peut en profiter.

Et comme vous avez un framework bien fait, vous pouvez toujours faire la chose suivante :

1. en fonction de la requête (cookie, url, etc) activer ou non le log ;
2. accumuler les logs pendant la requête ;
3. stocker le log dans memcache ou APC en fin de requête ;
4. flusher les informations sur le disque ou dans votre base de données toutes les x requêtes/minutes.

Notez que c’est la seule manière d’avoir le contexte du message au meilleur coût (pas d’introspection). Un inconvénient quand même, votre message est l’évaluation d’une chaîne de caractères, donc cela se lit moins bien dans le code. J’ai quand même trouvé une méthode pour logger dans Pluf, chouette.

Le rappel de l’existence de assert m’a été fait par François dans les commentaires ici, merci !

Mise à jour: Ceci est une utilisation détournée de la fonction assert, cela peut poser des problèmes si vous combinez cette approche avec du code utilisant assert pour réellement faire des tests. Ce qui me rassure c’est que dans l’intégralité du code PHP que j’utilise, incluant de nombreuses bibliothèques issues de PEAR, je n’ai pas trouvé une seule utilisation de assert.

---