Participer au site avec un Tip
Rechercher
 

Améliorations / Corrections

Vous avez des améliorations (ou des corrections) à proposer pour ce document : je vous remerçie par avance de m'en faire part, cela m'aide à améliorer le site.

Emplacement :

Description des améliorations :

Utilisation de l'API Log4J2

Utilisation du package java.util.logging Utilisation de l'API SLF4J



Accès rapide :
Introduction
Installation de Log4J 2
Installation manuelle
Installation par Maven
Produire des logs avec Log4J 2
Acquisition d'un logger
Les différents niveaux de logs
Produire un log à un niveau donné
Configurer vos logs
Gestion des appenders
Contrôler les niveaux de log
Attention aux problématiques de performances
Utilisation de l'outil Chainsaw

Introduction

Log4J est une API de log proposée par la fondation Apache et vous pouvez trouver ce logiciel sur son site officiel : http://logging.apache.org/log4j/2.x/ Le nom Log4J signifie Logging for Java.

la fondation Apache est très importante dans l'écosystème Java, car elle fournit un très grand nombre de librairies complémentaires, de très bonne facture, au Java SE et à Jakarta EE (ex Java EE).

Attention, historiquement parlant, il y a eut deux APIs de logging appelées Log4J. La première fut développée par la fondation Apache à partir de 2001. Cette version est maintenant abandonnée au profit de Log4J 2 : il s'agit d'une réécriture complète du moteur de log. Il n'y a donc aucune compatibilité entre les deux versions et la migration d'une version à l'autre nécessitera des modifications dans le code.

Comme l'API Log4J (première du nom) est apparue bien avant l'API JUL (java.util.logging), elle a été massivement utilisée. Lors du passage à Log4J 2, les utilisateurs historiques ont basculé sur cette nouvelle implémentation au détriment de JUL.

Installation de Log4J 2

Je vous propose deux solutions pour installer Log4J 2 : soit par le biais d'une installation manuelle, soit en utilisant l'outil Apache Maven.

Installation manuelle

Le logiciel Apache Log4J 2 peut être téléchargé sur son site officiel : http://logging.apache.org/log4j/2.x/download.html. Une fois l'archive téléchargée, vous y trouverez deux archive jars (Java ARchive) principales qui sont log4j-api-2.13.3.jar et log4j-core-2.13.3.jar (les numéros de versions pourront varier : je vous conseille toujours de prendre les versions les plus récentes). Placez ces deux fichiers dans un dossier lib à la racine de votre projet Eclipse.

Une fois les deux JARs placés dans le projet, il ne reste plus qu'à les ajouter au CLASSPATH. Avec Eclipse, cela peut se faire en cliquant avec le bouton droit de la souris sur ces archives, puis en sélectionnant « Build Path / Add to Build Path » (ou via la boîte de dialogue « Configure Build Path »). Une fois cette étape réalisée, les deux archives doivent être visible dans les librairies référencées par le projet, comme le montre la capture d'écran ci-dessous.

Ajout des jar de Log4J2 au CLASSPATH de la JVM

Installation par Maven

Une autre solution pour installer une librairie sur votre machine consiste à utiliser l'outil Apache Maven. Il s'agit d'un outil de construction de programme (ou outil de build) qui gère les dépendances. Nous n'avons pas encore vraiment parlé de Maven, mais nous le ferons dans un futur chapitre.

Pour ceux qui connaissent déjà Maven, voici la définition de la dépendance Log4J 2 pour votre projet Maven.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
<dependencies>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>2.13.3</version>
    </dependency>
    <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.13.3</version>
    </dependency>
</dependencies>
Définition d'une dépendance sur Log4J 2 dans Maven

Produire des logs avec Log4J 2

Pour produire des logs avec l'API Log4J 2, vous devez réaliser, à minima, deux étapes :

Dans une certaine mesure, on peut dire que Log4J 2 et l'API standard java.util.logging se ressemblent beaucoup. Si l'on connait déjà l'une des deux APIs, apprendre à manipuler l'autre est assez simple.

Acquisition d'un logger

Pour acquérir un logger, il faut utiliser la méthode statique LogManager.getLogger. Bien entendu, la classe LogManager doit être celle localisée dans le package org.apache.logging.log4j. D'autres packages peuvent aussi contenir une classe de même nom (et notamment le package java.util.logging) : il est donc important de faire très attention à l'import utilisé. Par le jeu subtil de la surcharge, votre méthode d'acquisition peut accepter en paramètre plusieurs types et notamment une chaîne de caractères. Il s'agit du nom du logger : il est très important, car il servira ultérieurement à configurer ce logger. Vous pouvez mettre le nom qui vous convient. Dans l'exemple suivant, j'imagine être dans un composant logiciel « Compo1 » et j'ai donc nommé mon logger de la même manière : cela me permettra de facilement configurer les loggers de toutes les classes de ce composant logiciel.

un composant logiciel est une unité fonctionnelle qui peut regrouper une ou plusieurs classes Java. En Java, un composant logiciel est souvent associé à un package de votre application.
 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog4J {

    // Récupération de notre logger.
    private static final Logger LOGGER =  LogManager.getLogger( "Compo1" );

    // Le point d'entrée du programme.
    public static void main( String [] args ) {

        // TODO: utiliser votre logger
        
    }
    
}
Fichier TestJUL.java : exemple d'instanciation d'un logger Log4J 2

Certains préfèrent utiliser la signature de la méthode getLogger acceptant un objet de type java.lang.Class. Voici un exemple d'instanciation en utilisant la classe courante comme nom de logger.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog4J {

    // Récupération de notre logger.
    private static final Logger LOGGER =  LogManager.getLogger( TestLog4J.class );

    // Le point d'entrée du programme.
    public static void main( String [] args ) {

        // TODO: utiliser votre logger
        
    }
    
}
Fichier TestJUL.java : exemple d'instanciation d'un logger Log4J 2 grâce à la classe courante

Je vous recommande d'utiliser cette seconde possibilité ! Effectivement, dans la configuration du moteur Log4J 2, il va être possible de dire que tous les loggers commençant par un préfixe doivent appliquer telle ou telle règle. Si le préfixe utilisé correspond au nom d'un package, toutes les classes de ce package seront configurées. De plus, le mécanisme est récursif.

Vous l'aurez remarqué, le logger est, à chaque fois, défini en tant que constante privée (private static final). Afin d'améliorer les performances de votre programme, il est important de respecter cette manière de faire. En tant que membre statique, l'instanciation du logger est sa configuration n'interviendront qu'une unique fois. De plus, le fait qu'il soit marqué comme étant statique garantira que la JVM pourra placer cette instance dans un metaspace (ou le perm dans les vieilles JVMs). L'activité du garbage collector en sera donc réduite. Je vous renvoie vers les chapitres dédiés au garbage collector pour de plus amples informations.

Il est à noter que vous utilisez une méthode statique de récupération du logger (la méthode LogManager.getLogger()). Pourquoi n'utilise-t-on pas un constructeur ? La raison est simple, plusieurs classes peuvent partager le même logger. Dans ce cas, on doit toujours demander le même nom de logger et la première classe qui le demande va lancer son instanciation et sa configuration. Les autres appels retourneront cette instance. Voici un exemple de code mettant en évidence ce point.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog4J {

    // Récupérations multiples de notre logger.
    private static final Logger LOGGER1 = LogManager.getLogger( "Compo1" );
    private static final Logger LOGGER2 = LogManager.getLogger( "Compo1" );

    // Le point d'entrée du programme.
    public static void main( String [] args ) {

        // On fait une comparaison de pointeurs pour bien vérifier que nous 
        // avons bien deux variables qui pointent sur la même instance.
        System.out.println( LOGGER1 == LOGGER2 );       // Affiche true !
        
    }
    
}
Pour un nom de logger, vous n'aurez qu'une unique instance.

Les différents niveaux de logs

Il nous faut maintenant bien comprendre les différents niveaux de logs avec l'API Log4J2. Pour ce faire, nous allons commencer par regarder un extrait du contenu de la classe org.apache.logging.log4j.Level.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
 24 
 25 
 26 
 27 
 28 
 29 
 30 
 31 
 32 
 33 
 34 
 35 
 36 
 37 
 38 
 39 
 40 
 41 
 42 
 43 
 44 
 45 
 46 
 47 
 48 
 49 
 50 
 51 
import org.apache.logging.log4j.Logger;

// Les imports

public final class Level implements Comparable<Level>, Serializable {

    // ...
    
    /**
     * No events will be logged.
     */
    public static final Level OFF;              // 0        == Integer.MIN_VALUE

    /**
     * A severe error that will prevent the application from continuing.
     */
    public static final Level FATAL;            // 100

    /**
     * An error in the application, possibly recoverable.
     */
    public static final Level ERROR;            // 200

    /**
     * An event that might possible lead to an error.
     */
    public static final Level WARN;             // 300

    /**
     * An event for informational purposes.
     */
    public static final Level INFO;             // 400

    /**
     * A general debugging event.
     */
    public static final Level DEBUG;            // 500

    /**
     * A fine-grained debug message, typically capturing the flow through the application.
     */
    public static final Level TRACE;            // 600

    /**
     * All events should be logged.
     */
    public static final Level ALL;              // 2147483647 == Integer.MAX_VALUE
    
    // ...
    
}
Un extrait de la classe java.util.logging.Level

Chaque niveau de log est associé à une valeur numérique lors de l'instanciation de la constante. J'ai rajouté les valeurs associées en commentaire à la suite de chaque niveau. Autoriser l'affichage des logs à un niveau donné active aussi tous les niveaux de logs ont une valeur numérique inférieure. Ainsi, si vous configurez les logs pour afficher à partir du niveau Level.INFO, vous couperez les niveaux supérieurs (Level.DEBUG et Level.TRACE, par contre vous activerez aussi tous les niveaux inférieurs (WARN, ERROR et FATAL).

Si, pour un logger donné vous le configurez au niveau Level.OFF (de valeur Integer.MIN_VALUE), aucun log sera produit, car tous les niveaux de log ont une valeur numérique supérieure. A l'opposé, si vous configurez votre logger au niveau Level.ALL (de valeur Integer.MAX_VALUE), tous les logs seront produits, car ces niveaux auront tous une valeur numérique inférieure.

Produire un log à un niveau donné

La première solution pour produire un log est d'utiliser la méthode log de votre logger. Voici un exemple d'utilisation de cette méthode.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog4J {

    // Récupération de notre logger.
    private static final Logger LOGGER =  LogManager.getLogger( TestLog4J.class );

    // Le point d'entrée du programme.
    public static void main( String [] args ) {
        
        // On produit un log de niveau informatif.
        LOGGER.log( Level.INFO, "Hello World with Log4J 2" );

        // On produit un log de niveau erreur.
        LOGGER.log( Level.ERROR, "Houston, we have a problem" );
        
    }

}
Exemple d'utilisation de la méthode Logger.log

Si vous lancez la classe, vous obtiendrez un résultat proche (la première information temporelle sera différente) de cet affichage.

15:28:49.663 [main] ERROR fr.koor.samples.log4j2.TestLog4J - Houston, we have a problem

Comme vous le constatez, le log informatif n'est pas affiché : c'est normal, car par défaut les logs sont activés qu'à partir du niveau Level.ERROR. Pour changer cela, il va falloir fournir un fichier de configuration pour Log4J 2.

Une autre solution consiste à utiliser des méthodes de convenance qui renvoient les appels sur Logger.log. Ces méthodes sont nommées avec le niveau de log associé (Logger.info, Logger.error...). Voici un exemple d'utilisation.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog4J {

    // Récupération de notre logger.
    private static final Logger LOGGER =  LogManager.getLogger( TestLog4J.class );

    // Le point d'entrée du programme.
    public static void main( String [] args ) {
        
        // On produit un log de niveau informatif.
        LOGGER.info( "Hello World with Log4J 2" );

        // On produit un log de niveau erreur.
        LOGGER.error( "Houston, we have a problem" );
        
    }

}
Exemple d'utilisation de la méthode Logger.log

Vous pouvez aussi générer des traces en y injectant les valeurs de vos variables ou encore les informations des exceptions constatées. Dans le cas où vous souhaitez injecter des valeurs, c'est la séquence {} qui permet de définir les points d'injections. Voici un exemple d'utilisation de ces possibilités.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
 24 
 25 
 26 
 27 
 28 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLog4J {

    // Récupération de notre logger.
    private static final Logger LOGGER =  LogManager.getLogger( TestLog4J.class );

    // Le point d'entrée du programme.
    public static void main( String [] args ) {
        
        // On produit un log de niveau informatif.
        LOGGER.log( Level.INFO, "Hello World with Log4J {}", 2 );

        try {
            int value = (int)( Math.random() * 2 );
            int result = 3 / value;
            LOGGER.info( "value == {} - result == {}", value, result );
        } catch( Exception exception ) {
            LOGGER.error( "Houston, we have a problem.", exception ); 
        }
        
    }

}
Exemple d'utilisation de la méthode Logger.log

Sous condition d'autoriser les logs de niveau informatifs (nous allons y revenir dans quelques instants), vous obtiendrez le résultat suivant quand aucune exception n'est déclenchée.

[main] INFO  | fr.koor.samples.log4j2.TestLog4J                             | Hello World with Log4J 2 (TestLog4J.java:16)
[main] INFO  | fr.koor.samples.log4j2.TestLog4J                             | value == 1 - result == 3 (TestLog4J.java:21)

Par contre, si une exception est déclenchée, vous pourrez avoir un résultat proche de celui-ci.

[main] INFO  | fr.koor.samples.log4j2.TestLog4J                             | Hello World with Log4J 2 (TestLog4J.java:16)
[main] ERROR | fr.koor.samples.log4j2.TestLog4J                             | Houston, we have a problem. (TestLog4J.java:23)
java.lang.ArithmeticException: / by zero
    at fr.koor.samples.log4j2.TestLog4J.main(TestLog4J.java:20) [bin/:?]

Configurer vos logs

Vous pouvez configurer Log4J 2 grâce à un fichier XML : si vous souhaitez qu'il soit vu par défaut, il faut qu'il s'appelle log4j2.xml. Il doit aussi être accessible à partir du CLASSPATH : dit autrement, vous devez le placer dans le dossier src de votre projet Eclipse et non pas à la racine du projet, comme le montre la capture d'écran suivante.

Emplacement du fichier de configuration de Log4J 2.

Et voici un premier exemple de contenu pour ce fichier de configuration. Quelques explications suivront.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config" status="WARN">

    <Appenders>
            
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" />
        </Console>
        
    </Appenders>

    <Loggers>
        
        <Root level="info">
            <AppenderRef ref="stdout" />
        </Root>
        
    </Loggers>

</Configuration>
Le fichier log4j2.xml pour la configuration du moteur de logs

Gestion des appenders

Log4J 2 définit la notion d'appender pour identifier la destination de vos logs. Il existe plusieurs types d'appenders et notamment :

Par exemple, si vous souhaitez envoyer vos logs sur la console, mais aussi dans un fichier logs.txt, vous pouvez utiliser la configuration suivante.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
 24 
 25 
 26 
 27 
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config" status="WARN">

    <Appenders>
            
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" />
        </Console>
        
        <File name="file" fileName="logs.txt">
            <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" />
        </File>
        
    </Appenders>

    <Loggers>
        
        <Root level="info">

            <AppenderRef ref="stdout" />
            <AppenderRef ref="file" />

        </Root>
        
    </Loggers>

</Configuration>
Le fichier log4j2.xml : deux appenders y sont définis

Comme vous le constater, il est important d'enregistrer votre appender dans la section <Root> sans quoi les logs ne seraient envoyés que sur la console. L'association est faite via l'attribut ref="file" qui doit correspondre à la valeur de l'attribut name de votre appender.

le tag <PatternLayout ... /> n'est pas obligatoire, mais en son absence, seul le message du log sera envoyé dans le fichier. Comme vous le constatez, j'ai utilisé le même pattern que celui utilisé sur la console.

Pour utiliser des fichiers tournants, je vous recommande la configuration ci-dessous.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
 24 
 25 
 26 
 27 
 28 
 29 
 30 
 31 
 32 
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config" status="WARN">

    <Appenders>
            
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" />
        </Console>
        
        <RollingFile name="rollingFile" fileName="logs/logs.txt"
                     filePattern="logs/logs-%d{yyyy-MM-dd}-%i.txt">
            <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" />
            <Policies>
                <TimeBasedTriggeringPolicy />
                <SizeBasedTriggeringPolicy size="10 MB"/>
            </Policies>
        </RollingFile>
        
    </Appenders>

    <Loggers>
        
        <Root level="info">

            <AppenderRef ref="stdout" />
            <AppenderRef ref="rollingFile" />

        </Root>
        
    </Loggers>

</Configuration>
Le fichier log4j2.xml : exemple de définition d'un appender de type

Les logs seront envoyés dans le fichier logs/logs.txt (attribut fileName). Vous constaterez qu'il y a deux définitions dans la section <Policies> : la première indique qu'il faut changer de fichier à chaque nouveau jour et la seconde indique que chaque fichier historisé ne pourra pas dépasser 10 MB. Ainsi si l'une des deux stratégies est activée, le fichier logs/logs.txt sera historisé puis remit à zéro. Les fichiers historisés seront nommés d'après ce pattern : logs/logs-%d{yyyy-MM-dd}-%i.txt. Vous aurez compris à quoi correspond le %d{yyyy-MM-dd} : il injecte la date courante dans le nom du fichier. Par contre, à quoi correspond le %i ? C'est très simple, chaque jour, vous pourrez produire plusieurs fichiers de logs (notamment à cause de la taille maximale du fichier) : la séquence %i injecte un index unique dans le nom d'un fichier.

Si vous souhaitez utiliser d'autres appenders, je vous recommande de lire la documentation officielle : toutes les possibilités de configuration y sont détaillées.

Contrôler les niveaux de log

Et maintenant la partie la plus importante : comment sélectionner les logs qui seront produits et ceux qui ne le seront pas ? On contrôle ces aspects dans la section <Loggers>. Notez que ce tag possède un attribut level : sa valeur correspond aux niveaux de logs autorisés par défaut. Dans l'exemple, les niveaux Level.INFO, Level.WARN, Level.ERROR et Level.FATAL sont autorisés (car tous, de valeur inférieure ou égale à celle de Level.INFO).

Outre cette valeur par défaut, vous pouvez rajouter des tags <Logger> pour configurer spécifiquement certains de vos loggers. Considérons la nouvelle configuration ci-dessous.

 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
 24 
<?xml version="1.0" encoding="UTF-8" ?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config" status="WARN">

    <Appenders>
            
        <Console name="stdout" target="SYSTEM_OUT">
            <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" />
        </Console>
        
    </Appenders>

    <Loggers>
        
        <Root level="error">

            <Logger name="fr.koor.samples.log4j2" level="info" />

            <AppenderRef ref="stdout" />

        </Root>
        
    </Loggers>

</Configuration>
Le fichier log4j2.xml : gestion de logger

Du point de vue de l'appender utilisé, on envoie les logs sur la console (j'ai retiré la possibilité de stocker les logs sur un fichier). Par défaut, seules les erreurs seront tracées : cela est indiqué avec le niveau par défaut précisé sur le tag <Root level="error">. Si votre projet contient de nombreux packages, tous les loggers de ces différents packages sont donc limités à ne tracer que les erreurs (fatales ou non).

Par contre, il y a une exception : tous les loggers dont le nom commence par fr.koor.samples.log4j2 seront quant à eux configurés pour tracer à partir du niveau informatif.

Si vous souhaitez changer la configuration, arrêtez le programme, modifiez le fichier XML à votre convenance, puis relancez votre programme. La nouvelle configuration devrait être prise en considération.

Attention aux problématiques de performances

mal utilisés, vos logs peuvent consommer beaucoup de ressources pour pas forcément grand chose. Le mieux, pour comprendre cette problématique de performance, c'est un petit exemple concret : nous allons donc considérer l'exemple suivant.
 1 
 2 
 3 
 4 
 5 
 6 
 7 
 8 
 9 
 10 
 11 
 12 
 13 
 14 
 15 
 16 
 17 
 18 
 19 
 20 
 21 
 22 
 23 
 24 
 25 
 26 
 27 
 28 
 29 
 30 
 31 
 32 
 33 
 34 
 35 
 36 
 37 
 38 
 39 
 40 
 41 
 42 
 43 
 44 
 45 
 46 
 47 
 48 
 49 
package fr.koor.samples.log4j2;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

public class TestLogGuard {

    // Un compteur pour démultiplier la problématique 
    private static final int LOOP_COUNT = 10_000_000;

    // Récupération de notre logger.
    private static final Logger LOGGER = LogManager.getLogger( TestLogGuard.class );

    // Deux attributs utiles pour notre simulation de toString.
    private String aName = "AName";
    private double aValue = Math.random() * 100;
    
    // On simule un traitement itératif qui produit régulièrement des logs.
    public void doSomething() {
        for (int i = 0; i < LOOP_COUNT; i++) {
            aValue += 0.01;
            LOGGER.info( i + ": A message " + this );
        }
    }

    /*
     * Une méthode pour transformer une instance en chaîne de caractères.
     * L'idée est de simuler l'affichage d'objets complexes dans les logs,
     * ce qui est très utile quand on trace l'activité d'un programme.
     */
    @Override
    public String toString() {
        return "TestLogGuard[aName=" + aName + ", aValue=" + aValue + "]";
    }
    

    // Le lancement de la démonstration.
    public static void main(String[] args) {
        TestLogGuard test = new TestLogGuard();
        
        // On prend des mesures de temps pour chronométrer le temps pris par doSomething.
        long begin = System.currentTimeMillis();
        test.doSomething();
        long end = System.currentTimeMillis();
        
        System.out.println( "Duration : " + (end - begin)  + "ms" );
    }
    
}
Un petit exemple de code pour comprendre une problématique de performance.

Si vous activez les logs pour notre classe, un grand nombre de traces seront affichées sur la console. C'est normal et étant donné le nombre de tours de boucle, je vous conseille de terminer le processus sans en attendre la fin.

Souvent, une fois la mise en production effectué, les logs de l'application sont restreints au niveau Level.ERROR (voir Level.WARN) : l'idée étant de ne pas tout enregistrer, mais quand même de tracer les problèmes s'ils surviennent. Le plus simple pour obtenir ce résultat, c'est de modifier ainsi le fichier de configuration de Log4J2.

<?xml version="1.0" encoding="UTF-8" ?> <Configuration xmlns="http://logging.apache.org/log4j/2.0/config" status="WARN"> <Appenders> <Console name="stdout" target="SYSTEM_OUT"> <PatternLayout pattern="[%t] %-5p | %-60c | %m (%F:%L)%n" /> </Console> </Appenders> <Loggers> <Root level="error"> <AppenderRef ref="stdout" /> </Root> </Loggers> </Configuration>

Vous pouvez maintenant relancer le programme et, normalement, aucun log ne sera produit. Seul l'appel à System.out.println() devrait vous donner le temps nécessaire pour ne pas produire 10 millions de logs. Sur ma machine cela prend environ 6 secondes, mais le temps peut varier en fonction de la puissance de calcul de votre PC.

Je ne sais pas trop ce que vous en pensez, mais croyez-moi sur parole : c'est beaucoup trop ! Dans ce programme, on pense 5 secondes à produire des chaînes de caractères pour rien. Cela se passe au niveau de la ligne 22 : avant de rentrer dans l'appel à LOGGER.info, on évalue l'expression i + ": A message " + this. Or, si le log ne doit pas être produit, on a quand même fait les concaténations (plus celles cachées dans le toString).

Pour vous en convaincre, veuillez modifier le code de la méthode doSomething ainsi :

 1 
 2 
 3 
 4 
 5 
 6 
 7 
public void doSomething() {
    for (int i = 0; i < LOOP_COUNT; i++) {
        aValue += 0.01;
        if ( LOGGER.isInfoEnabled() )
            LOGGER.info( i + ": A message " + this );
    }
}
Utilisation d'un « log guard »

La différence, dans ce nouveau code, c'est l'utilisation de la condition if ( LOGGER.isInfoEnabled() ) : on parle de « log guard » (un gardien de log). Cette condition permet de vérifier si le log doit être produit ou non. Certes, la méthode info fait normalement ce test, mais dans notre cas cela nous évitera de réaliser les concaténations avant l'appel à la méthode.

Relancez le programme avec le « log guard » et constatez la différence. Sur ma machine, cela ne prend plus que 40 millisecondes. CQFD : nous avions donc bien passé environ 6 secondes à produire de chaines de caractères totalement inutiles !

si le message à tracer ne contient aucune concaténation, le « log guard » n'est plus nécessaire. Si vous laissez le « log guard » pour protéger un log sur une chaîne de caractères constante et que le niveau de log est autorisé, la vérification aura lieu deux fois : c'est pas top non plus.

Une autre manière de régler le problème de performance, consiste à utiliser les logs formatés : cette technique ressemble un peu à l'utilisation de la méthode System.out.printf(), en définissant des points d'injections dans une chaîne de caractères servant de format. Afin de tester cette possibilité, je vous propose de réécrire le contenu de la méthode doSomething tel que proposé dans l'exemple ci-dessous. Relancez le programme. Sur ma machine, je ne mets que 85 millisecondes pour terminer les 10 millions de tours de boucles.

 1 
 2 
 3 
 4 
 5 
 6 
public void doSomething() {
    for (int i = 0; i < LOOP_COUNT; i++) {
        aValue += 0.01;
        LOGGER.info( "{}: A message {}", i, this );
    }
}
Utilisation d'un log formaté
personnellement, c'est la technique que je préconise vivement. Certes le programme prend un petit peu plus de temps, mais cette technique évite la présence des « log guards », souvent un peu lourd à écrire systématiquement : de mon point de vue, la lisibilité du code en est accrue.

En synthèse :

Style de code Temps de réponse pour 10 millions de logs désactivés
LOGGER.info( i + ": A message " + this ); 6000 ms
if ( LOGGER.isInfoEnabled() )
    LOGGER.info( i + ": A message " + this );
40 ms
LOGGER.info( "{}: A message {}", i, this ); 85 ms

Au terme de cette démonstration, j'espère vous avoir convaincu de faire attention aux concaténations dans vos logs.

Utilisation de l'outil Chainsaw

Pour finir ce chapitre, j'aimerais vous parler rapidement d'un outil graphique permettant de visualiser et filtrer les logs que vous avez produits. Cet outil se nomme « Chainsaw », il est gratuit et il est aussi proposé par la fondation Apache. Pour télécharger ce logiciel, rendez-vous avec votre navigateur favori sur cette page : https://logging.apache.org/.

vous constaterez sur cette page que la fondation Apache propose des portages de Log4J pour d'autres langages de programmation (C++, PHP...).

Vous devriez y trouver un lien vers le site officiel de Chainsaw : activez, bien entendu, ce lien hypertexte. Cet outil permet de travailler sur des fichiers de logs produits par Log4J 2, mais aussi par les autres API de log pour C++, PHP... C'est un outil graphique codé en Java via l'API Swing. Un des avantages à utiliser un outil graphique, c'est la colorisation en fonction des niveaux de logs.

Exemple d'affichage d'un fichier de log avec l'outil Chainsaw

Un tutoriel sur Chainsaw est directement proposé dans l'outil. D'autres outils de visualisation de logs existent sur Internet.



Utilisation du package java.util.logging Utilisation de l'API SLF4J