Quand on découvre l'AOP (
programmation orientée aspect) à travers les blogs et autres résultats que nous propose Google, on tombe immanquablement sur un exemple d'instrumentation du code par des logs.
Si d'un point de vue didactique c'est un exemple qui a l'avantage d'être parlant pour tout le monde, d'un point de vue technique c'est une aberration :
- les outils de logs modernes déterminent le nom de la classe/méthode et numéro de ligne à la volée, il serait donc dommage de perdre cette info dans nos logs. Or, en passant par un aspect, ce mécanisme va pointer dans le greffon de l'aspect, et pas là où on l'a appliqué
- chaque ligne de log va nécessiter l'invocation du greffon, la copie des arguments, peut être même la construction d'un logger pour la classe considérée. Des millièmes de secondes qu'on va répéter des millions de fois, au final un dégradation mesurable des performances du code (si vous n'y croyez pas, j'ai vu une appli perdre 10% de son temps dans des mécanismes de log mal fichus).
Evidemment, parler de gestion transactionnel pour montrer l'utilisation de l'AOP n'est pas le plus simple...
Je rebondis cependant sur ce problème pédagogique : l'idée de base est bonne
Personne n'apprécie de devoir lire des logs vides, mais n'aime pas pour autant passer du temps à ajouter des logs DEBUT/FIN dans tout le code, et voir une méthode initialement si belle et explicite polluée par des lignes de logger.trace( param = truc ).
J'ai donc créé
Logeek, un outil d'instrumentation du bytecode qui ajoute ces fameux logs si indispensables et si disgracieux. Contrairement à un outil d'AOP, Logeek fait de l'instrumentation agressive en ajoutant directement un attribut
logger et le traçage des paramètres dans chaque méthode, là où AspectJ déporterait l'appel dans le greffon.
En gros, partant de ce code :
public boolean doSomething( String value, int count )
{
System.out.println( "done" );
return true;
}
Loggek va modifier le bytecode pour qu'il ressemble à ceci (en pseudo-code puisque le source n'est pas modifié, et le bytecode n'a pas exactement cette structure)
private static transient Logger __logger
= LoggerFactory.getLogger( Foo.class );
public boolean doSomething(String value, int count)
{
boolean returnedvalue;
try
{
__logger.debug( "{" );
__logger.trace( " value = {}", value );
__logger.trace( " count = {}", count );
System.out.println( "done" );
returnedvalue = true;
}
catch (Throwable throwable )
{
__logger.trace( " throws {}", throwable );
throw throwable;
}
__logger.trace( " return {}", returnedvalue );
__logger.debug( "}" );
return returnedvalue;
}
Pour comparaison, AspectJ produirait une transformation du bytecode qui ressemblerait plus à ceci :
public boolean doSomething(String value, int count)
{
boolean returnedvalue;
try
{
String arg1 = value.clone();
int arg2 = count.clone();
LoggingAspect.aspectOf().before( this, arg1, arg2 );
System.out.println( "done" );
returnedvalue = true;
}
catch (Throwable throwable )
{
LoggingAspect.aspectOf().afterThrowable( this, t );
throw throwable;
}
LoggingAspect.aspectOf().after( this, returnedvalue );
return returnedvalue;
}
La différence est subtile, mais dans ce second cas la source du log est le greffon de l'aspect, pas le code instrumenté, et au passage on paye même en mode TRACE (généralement désactivé) le prix d'une copie d'arguments et de plusieurs appels de méthodes.
Avec ce mécanisme activé on obtient donc, en TRACE, toutes les infos utiles sur le code exécuté. L'utilisation de SLF4J permet de ne pas s'encombrer de if logger.isDebugEnabled(), mais l'outil pourrait tout aussi bien se baser sur l'API log4j et ajouter ces contrôles.
Pour marquer le début/fin des méthodes j'utilise des accolades, car dans un éditeur un peu malin (comme NotePad++) le curseur positionné à côté met immédiatement en évidence sa petite soeur - c'est bien pratique ;)
Tout ça via un plugin Maven, qu'il suffit d'ajouter à son POM.xml (qui sans ça serait bien trop concis)
<plugin>
<groupid>fr.loof.logeek</groupid>
<artifactid>logeek-maven-plugin</artifactid>
<executions>
<execution>
<goals>
<goal>instrument</goal>
</goals>
<configuration>
<includes>
<include>**/*.class</include>
</includes>
<transformer>fr.loof.logeek.Slf4jLogging</transformer>
</configuration>
</execution>
</executions>
</plugin>
Logeek devrait être déployé dans le dépôt Maven
central sous peu, en version 0.0.1. Je suis ouvert à toutes vos suggestions pour la 0.0.2 :)
