Performance statistics : Perf4J pour le code java

Le framework Perf4J offre une façon élégante de faire des statistiques de performance de notre code java.

Le site Perf4J donne cette analogie qui résume bien son apport :

''Perf4J is a set of utilities for calculating and displaying performance statistics for Java code.
For developers who are familiar with logging frameworks such as log4j or logback, an analogy helps to describe Perf4J:

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()''

Ainsi comme le log4J (ou toute autre implémentation de trace log) est devenu un standard (norme), le Perf4J pourrait aussi l'être.

Notez que le terme de performance est employé dans un sens très large. Seul le temps de réponse nous préoccupe.

La démo présentée ci-après est construite avec Perf4J basé sur l'AOP de Spring ce qui permet de ne pas polluer le code existant.

Pour réaliser cette démo de façon non intrusive, l'annotation @Profiled de Perf4J et l'AOP de Spring sont utilisés.

Les versions de Spring 2+ et jdk5+ sont utilisées.

Passons à la mise en pratique de ce framework avec l'AOP Spring.

Perf4J et Spring AOP permettent d'obtenir les stats de performance avec peu de code qui est très "user friendly".

Voici les cinq étapes de la démo :

ETAPE 1. Compléter le pom du projet maven (ajout de 2 dépendances)

ETAPE 2. Ecrire le fichier de configuration de Spring (AOP)

ETAPE 3. Ajout d'une annotation aux méthodes à surveiller

ETAPE 4. Ajouter ou compléter log4j.xml

ETAPE 5. Ecrire un test JUnit

<version>0.9.16</version>

</dependency>
<dependency>

<groupId>commons-jexl</groupId>
<artifactId>commons-jexl</artifactId>
<version>1.1</version>
<scope>runtime</scope>

</dependency>



%%%
__ETAPE 2__. Ecrire le fichier de configuration de Spring (AOP)


<?xml version="1.0" encoding="UTF-8"?>
<! Note the aop namespace defined in the top-level >
<beans xmlns="http://www.springframework.org/schema/beans"

 xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xmlns:aop="http://www.springframework.org/schema/aop"
 xsi:schemaLocation="http://www.springframework.org/schema/beans
 http://www.springframework.org/schema/beans/spring-beans-2.0.xsd
 http://www.springframework.org/schema/aop
 http://www.springframework.org/schema/aop/spring-aop-2.0.xsd">
 <!-- Including this aspectj-autoproxy element will cause spring 
 to automatically create proxies around any beans defined in this file 
that match the pointcuts of any aspects defined in this file.-->
 <aop:aspectj-autoproxy/>
<!--Declare the TimingAspect that we want to weave into the

other beans defined in this config file.-->


<bean id="timingAspect" class="org.perf4j.log4j.aop.TimingAspect"/>

<bean id="primeGen" class="fr.netapsys.blogs.PrimeGenerator">

    <property name="current" value="1"/>

</bean>
</beans>


Le bean "primeGen" de type PrimeGenerator est déclaré avec sa propriété "current" initialisée.
Seule la définition du bean "primeGen" pourrait changer dans ce fichier.

La classe PrimeGenerator respecte l'interface IPrimeGenerator ci-dessous:

package fr.netapsys.blogs;
import java.math.BigInteger;
public interface IPrimeGenerator {
BigInteger nextPrime();
}


Et le code de la classe d'implémentation PrimeGenerator est:

package fr.netapsys.blogs;
import java.math.BigInteger;
import org.perf4j.aop.Profiled;

public class PrimeGenerator implements IPrimeGenerator {

 private BigInteger current = new BigInteger("0");
 @Override
 public BigInteger nextPrime() {
      current = current.nextProbablePrime();
      return current;
 }
  //... getter/setters ...

}



%%%
__ETAPE 3__. Ajout d'une annotation aux méthodes à surveiller

Dans notre cas, on ajoute l'annotation @Profiled à la méthode nextPrime() de la classe PrimeGenerator comme suit:

@Profiled public BigInteger nextPrime()


C'est ici que l'AOP de Spring opère. Cette annotation permet de tracer les performances de calcul du prochain entier __premier__.


%%%
__ETAPE 4__. Ajouter ou compléter log4j.xml

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="false"

      xmlns:log4j="http://jakarta.apache.org/log4j/">
<!--This default ConsoleAppender is used to log

all NON perf4j messages to System.out-->

<appender name="console" class="org.apache.log4j.ConsoleAppender">

    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%-5p %c{1} - %m%n"/>
    </layout>

</appender>

<! Perf4J appenders >

<!--This AsyncCoalescingStatisticsAppender groups StopWatch

log messages into GroupedTimingStatistics messages which it
sends on the file appender defined below-->


<appender name="statistics"

   class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">  
 <appender-ref ref="fileAppender"/>

</appender>

<!-- This file appender is used to output
aggregated performance statistics -->

<appender name="fileAppender"

    class="org.apache.log4j.FileAppender">
   <param name="File" value="./perf4jStats.log"/>
   <layout class="org.apache.log4j.PatternLayout">
        <param name="ConversionPattern" value="%m%n"/>
    </layout>

</appender>

<! Loggers >
<!--The Perf4J logger.
Note that org.perf4j.TimingLogger is the value of the
org.perf4j.StopWatch.DEFAULT_LOGGER_NAME constant.
Also, note that additivity is set to false, which is usually what
is desired. this means that timing statements will only be sent
to this logger and NOT to upstream loggers.-->

<logger name="org.perf4j.TimingLogger" additivity="false">

   <level value="INFO"/>
   <appender-ref ref="statistics"/>

</logger>

<!--The root logger sends all log statements EXCEPT those sent

to the perf4j logger to System.out. -->


<root>

   <level value="INFO"/>
   <appender-ref ref="console"/>

</root>
</log4j:configuration>

 
Notez que le format xml du fichier log4j est nécessaire pour Perf4J.


%%%
__ETAPE 5__. Ecrire un test JUnit

package fr.netapsys.tests;

import java.math.BigInteger;

import org.junit.Assert;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;
import fr.netapsys.blogs.PrimeGenerator;

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration(locations="classpath:/META-INF/spring/spring.xml")
public class TestPrimeGeneratorTest {

 @Autowired private IPrimeGenerator primeGen;
 @Test public void test() {
  BigInteger p = primeGen.nextPrime();
  System.out.println("nextPrime() :\t" + p);
  // current=1 in spring.xml
  Assert.assertTrue(p.intValue() == 2);
 }

}


Enfin, lancer dans la console dos la commande ;

mvn test


Vous verrez, en plus des sorties console, les stats de performance dans le fichier perf4jStats.log du log4j.xml.
Ces sorties ressemblent à:
///Performance Statistics
Tag                   Avg(ms)   Min    Max  Std Dev  Count
nextPrime            41,0      41    41      0,0           1

On peut, en configurant un appender dans log4j.xml, obtenir des traces et des graphes sur les performances de notre code.
Tout cela sans polluer le code existant.

On peut aussi décider, comme avec log4J, d'activer ou non les traces de performances toujours via le fichier de configuration log4j.xml.

En écrivant, dans notre test, une boucle appelant la méthode nextPrime(), on obtient un tableau de performance plus intéressant.

@Enjoy

Laisser un commentaire

Votre adresse de messagerie ne sera pas publiée. Les champs obligatoires sont indiqués avec *

Captcha *

Ce site utilise Akismet pour réduire les indésirables. En savoir plus sur comment les données de vos commentaires sont utilisées.