Dans log4j, la vérification de isDebugEnabled avant la journalisation améliore-t-elle les performances?

207

J'utilise Log4J dans mon application de journalisation. Auparavant, j'utilisais l'appel de débogage comme:

Option 1:

logger.debug("some debug text");

mais certains liens suggèrent qu'il est préférable de vérifier d' isDebugEnabled()abord, comme:

Option 2:

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text");
}

Ma question est donc "l' option 2 améliore-t-elle les performances de quelque manière que ce soit? ".

Parce que dans tous les cas, le framework Log4J a la même vérification pour debugEnabled. Pour l'option 2, cela peut être avantageux si nous utilisons plusieurs instructions de débogage dans une seule méthode ou classe, où le framework n'a pas besoin d'appeler la isDebugEnabled()méthode plusieurs fois (à chaque appel); dans ce cas, il n'appelle la isDebugEnabled()méthode qu'une seule fois, et si Log4J est configuré pour déboguer le niveau, il appelle en fait la isDebugEnabled()méthode deux fois:

  1. En cas d'affectation de valeur à la variable debugEnabled, et
  2. En fait appelé par la méthode logger.debug ().

Je ne pense pas que si nous écrivons plusieurs logger.debug()instructions dans la méthode ou la classe et la debug()méthode d' appel selon l'option 1, cela représente une surcharge pour le cadre Log4J par rapport à l'option 2. Étant donné qu'il isDebugEnabled()s'agit d'une très petite méthode (en termes de code), elle pourrait être un bon candidat pour la doublure.

Guerrier silencieux
la source

Réponses:

248

Dans ce cas particulier, l'option 1 est meilleure.

L'instruction guard (vérification isDebugEnabled()) est là pour éviter un calcul potentiellement coûteux du message de journal lorsqu'elle implique l'invocation des toString()méthodes de divers objets et la concaténation des résultats.

Dans l'exemple donné, le message de journal est une chaîne constante, donc laisser l'enregistreur le supprimer est tout aussi efficace que de vérifier si l'enregistreur est activé, et cela réduit la complexité du code car il y a moins de branches.

Mieux encore est d'utiliser un cadre de journalisation plus à jour où les instructions log prennent une spécification de format et une liste d'arguments à remplacer par l'enregistreur, mais "paresseusement", uniquement si l'enregistreur est activé. C'est l'approche adoptée par slf4j .

Voir ma réponse à une question connexe pour plus d'informations et un exemple de faire quelque chose comme ça avec log4j.

erickson
la source
3
log5j étend log4j de la même manière que slf4j
Bill Michell
C'est également l'approche de java.util.Logging.
Paul
@Geek Il est plus efficace lorsque l'événement de journal est désactivé car le niveau de journal est défini sur élevé. Consultez la section intitulée «La nécessité d'une journalisation conditionnelle» dans ma réponse ici.
erickson
1
Cela a-t-il changé dans log4j 2?
SnakeDoc
3
@SnakeDoc Non. Il est fondamental d'appeler une méthode: les expressions dans les listes d'arguments de méthode sont effectivement évaluées avant l'appel. Si ces expressions sont a) jugées coûteuses et b) souhaitées uniquement sous certaines conditions (par exemple lorsque le débogage est activé), votre seul choix est de mettre une vérification de condition autour de l'appel, et le framework ne peut pas le faire pour vous. Le problème avec les méthodes de journalisation basées sur le formateur est que vous pouvez passer des objets (qui sont essentiellement gratuits), et l'enregistreur n'appellera toString()que si nécessaire.
SusanW
31

Étant donné que dans l'option 1, la chaîne de message est une constante, il n'y a absolument aucun gain à encapsuler l'instruction de journalisation avec une condition, au contraire, si l'instruction de journal est activée pour le débogage, vous évaluerez deux fois, une fois dans la isDebugEnabled()méthode et une fois dans debug()méthode. Le coût d'invocation isDebugEnabled()est de l'ordre de 5 à 30 nanosecondes, ce qui devrait être négligeable pour la plupart des applications pratiques. Ainsi, l'option 2 n'est pas souhaitable car elle pollue votre code et n'offre aucun autre gain.

Ceki
la source
17

L'utilisation de isDebugEnabled()est réservée lorsque vous créez des messages de journal en concaténant des chaînes:

Var myVar = new MyVar();
log.debug("My var is " + myVar + ", value:" + myVar.someCall());

Cependant, dans votre exemple, il n'y a pas de gain de vitesse car vous enregistrez simplement une chaîne et n'effectuez pas d'opérations telles que la concaténation. Par conséquent, vous ajoutez simplement du ballonnement à votre code et le rendez plus difficile à lire.

J'utilise personnellement les appels au format Java 1.5 dans la classe String comme ceci:

Var myVar = new MyVar();
log.debug(String.format("My var is '%s', value: '%s'", myVar, myVar.someCall()));

Je doute qu'il y ait beaucoup d'optimisation mais c'est plus facile à lire.

Notez cependant que la plupart des API de journalisation proposent un formatage comme celui-ci: slf4j, par exemple, fournit les éléments suivants:

logger.debug("My var is {}", myVar);

ce qui est encore plus facile à lire.

Alex
la source
8
Votre utilisation de String.format (...), tout en facilitant la lecture de la ligne de journal, peut en fait avoir un impact négatif sur les performances. La manière SLF4J de faire cela envoie les paramètres dans la méthode logger.debug et là l'évaluation de isDebugEnabled est effectuée avant la construction de la chaîne. Comme vous le faites, avec String.format (...), la chaîne sera construite avant l'appel de la méthode à logger.debug, vous aurez donc payé la pénalité de la construction de la chaîne même si le niveau de débogage est pas activé. Désolé pour la sélection, j'essaye juste d'éviter toute confusion pour les débutants ;-)
StFS
2
String.format est 40 fois plus lent que concat & slf4j a une limitation de 2 paramètres Voir les nombres ici: stackoverflow.com/questions/925423/… J'ai vu de nombreux graphiques de profileur où l'opération de formatage est gaspillée dans les instructions de débogage lorsque le système de production est en cours d'exécution au niveau du journal INFO ou ERREUR
AztecWarrior_25
8

Version courte: Vous pourriez aussi bien faire la vérification booléenne isDebugEnabled ().

Raisons:
1- Si logique / chaîne compliquée concat. est ajouté à votre déclaration de débogage, vous aurez déjà la vérification en place.
2- Vous n'avez pas à inclure sélectivement l'instruction sur les instructions de débogage "complexes". Toutes les déclarations sont incluses de cette façon.
3- L'appel de log.debug exécute ce qui suit avant de se connecter:

if(repository.isDisabled(Level.DEBUG_INT))
return;

C'est essentiellement la même chose que le journal des appels. ou chat. isDebugEnabled ().

TOUTEFOIS! C'est ce que pensent les développeurs de log4j (comme c'est le cas dans leur javadoc et vous devriez probablement y aller.)

C'est la méthode

public
  boolean isDebugEnabled() {
     if(repository.isDisabled( Level.DEBUG_INT))
      return false;
    return Level.DEBUG.isGreaterOrEqual(this.getEffectiveLevel());
  }

C'est le javadoc pour ça

/**
*  Check whether this category is enabled for the <code>DEBUG</code>
*  Level.
*
*  <p> This function is intended to lessen the computational cost of
*  disabled log debug statements.
*
*  <p> For some <code>cat</code> Category object, when you write,
*  <pre>
*      cat.debug("This is entry number: " + i );
*  </pre>
*
*  <p>You incur the cost constructing the message, concatenatiion in
*  this case, regardless of whether the message is logged or not.
*
*  <p>If you are worried about speed, then you should write
*  <pre>
*    if(cat.isDebugEnabled()) {
*      cat.debug("This is entry number: " + i );
*    }
*  </pre>
*
*  <p>This way you will not incur the cost of parameter
*  construction if debugging is disabled for <code>cat</code>. On
*  the other hand, if the <code>cat</code> is debug enabled, you
*  will incur the cost of evaluating whether the category is debug
*  enabled twice. Once in <code>isDebugEnabled</code> and once in
*  the <code>debug</code>.  This is an insignificant overhead
*  since evaluating a category takes about 1%% of the time it
*  takes to actually log.
*
*  @return boolean - <code>true</code> if this category is debug
*  enabled, <code>false</code> otherwise.
*   */
Andrew Carr
la source
1
Merci d'avoir inclus le JavaDoc. Je savais que j'avais déjà vu ce conseil quelque part auparavant et j'essayais de trouver une référence définitive. C'est, sinon définitif, du moins très bien informé.
Simon Peter Chappell
7

Comme d'autres l'ont mentionné, l'utilisation de l'instruction guard n'est vraiment utile que si la création de la chaîne prend du temps. Des exemples spécifiques de cela sont lorsque la création de la chaîne déclenchera un chargement paresseux.

Il convient de noter que ce problème peut être résolu en utilisant Simple Logging Facade pour Java ou (SLF4J) - http://www.slf4j.org/manual.html . Cela permet des appels de méthode tels que:

logger.debug("Temperature set to {}. Old temperature was {}.", t, oldT);

Cela ne convertira les paramètres transmis en chaînes que si le débogage est activé. SLF4J comme son nom l'indique n'est qu'une façade et les appels de journalisation peuvent être passés à log4j.

Vous pouvez également très facilement "rouler votre propre" version de ceci.

J'espère que cela t'aides.

Pablojim
la source
6

L'option 2 est meilleure.

En soi, cela n'améliore pas les performances. Mais cela garantit que les performances ne se dégradent pas. Voici comment.

Normalement, nous attendons logger.debug (someString);

Mais généralement, à mesure que l'application grandit, change de nombreuses mains, en particulier les développeurs novices, vous pouvez voir

logger.debug (str1 + str2 + str3 + str4);

etc.

Même si le niveau de journalisation est défini sur ERREUR ou FATAL, la concaténation des chaînes se produit! Si l'application contient beaucoup de messages de niveau DEBUG avec des concaténations de chaînes, alors il faut certainement un impact sur les performances, en particulier avec jdk 1.4 ou inférieur. (Je ne sais pas si les versions ultérieures de jdk internall font un stringbuffer.append ()).

C'est pourquoi l'option 2 est sûre. Même les concaténations de chaînes ne se produisent pas.

Sathya
la source
3

Comme @erickson, cela dépend. Si je me souviens bien, isDebugEnabledest déjà intégré dans la debug()méthode de Log4j.
Tant que vous ne faites pas de calculs coûteux dans vos instructions de débogage, comme la boucle sur des objets, effectuez des calculs et concaténez des chaînes, vous êtes d'accord à mon avis.

StringBuilder buffer = new StringBuilder();
for(Object o : myHugeCollection){
  buffer.append(o.getName()).append(":");
  buffer.append(o.getResultFromExpensiveComputation()).append(",");
}
log.debug(buffer.toString());

serait mieux que

if (log.isDebugEnabled(){
  StringBuilder buffer = new StringBuilder();
  for(Object o : myHugeCollection){
    buffer.append(o.getName()).append(":");
    buffer.append(o.getResultFromExpensiveComputation()).append(",");
  }
  log.debug(buffer.toString());
}
Michael Myers
la source
3

Pour une seule ligne , j'utilise un ternaire à l'intérieur du message de journalisation, de cette façon je ne fais pas la concaténation:

ej:

logger.debug(str1 + str2 + str3 + str4);

Je fais:

logger.debug(logger.isDebugEnable()?str1 + str2 + str3 + str4:null);

Mais pour plusieurs lignes de code

ej.

for(Message mess:list) {
    logger.debug("mess:" + mess.getText());
}

Je fais:

if(logger.isDebugEnable()) {
    for(Message mess:list) {
         logger.debug("mess:" + mess.getText());
    }
}
rbeltrand
la source
3

Étant donné que de nombreuses personnes consultent probablement cette réponse lors de la recherche de log4j2 et que presque toutes les réponses actuelles ne tiennent pas compte de log4j2 ou des modifications récentes, cela devrait, espérons-le, répondre à la question.

log4j2 prend en charge les fournisseurs (actuellement leur propre implémentation, mais selon la documentation, il est prévu d'utiliser l'interface fournisseur de Java dans la version 3.0). Vous pouvez en lire un peu plus à ce sujet dans le manuel . Cela vous permet de mettre la création de messages de journal coûteux dans un fournisseur qui crée le message uniquement s'il va être enregistré:

LogManager.getLogger().debug(() -> createExpensiveLogMessage());
Marcono1234
la source
2

Il améliore la vitesse car il est courant de concaténer des chaînes dans le texte de débogage, ce qui coûte cher, par exemple:

boolean debugEnabled = logger.isDebugEnabled();
if (debugEnabled) {
    logger.debug("some debug text" + someState);
}
À M
la source
1
Si nous utilisons jdk 1.5 et versions ultérieures, je pense que les chaînes concaténées ne feront aucune différence.
Silent Warrior
Comment venir? Que ferait JDK5 différemment?
javashlook
1
Dans jdk 1.5, si nous concaténons des chaînes dans une seule instruction, alors en interne, il utilise uniquement la méthode StringBuffer.append (). Cela n'affecte donc pas les performances.
Silent Warrior
2
La concaténation de chaînes prend sans aucun doute du temps. Cependant, je ne suis pas sûr de le qualifier de «cher». Combien de temps est économisé dans l'exemple ci-dessus? Par rapport à ce que fait réellement le code environnant? (par exemple, lecture de bases de données ou calcul en mémoire). Je pense que ce genre de déclarations doit être nuancé
Brian Agnew
1
Même JDK 1.4 ne créera pas de nouveaux objets String avec une simple concaténation de chaînes. La pénalité de performance vient de l'utilisation de StringBuffer.append () lorsqu'aucune chaîne ne doit être affichée du tout.
javashlook
1

Depuis la version Log4j2.4 (ou slf4j-api 2.0.0-alpha1), il est préférable d'utiliser une API fluide (ou la prise en charge lambda Java 8 pour la journalisation paresseuse ), prenant en charge l' Supplier<?>argument de message de journal, qui peut être fourni par lambda :

log.debug("Debug message with expensive data : {}", 
           () -> doExpensiveCalculation());

OU avec l'API slf4j:

log.atDebug()
            .addArgument(() -> doExpensiveCalculation())
            .log("Debug message with expensive data : {}");
Dan Brandt
la source
0

Si vous utilisez l'option 2, vous effectuez une vérification booléenne qui est rapide. Dans la première option, vous effectuez un appel de méthode (en poussant des choses sur la pile), puis en effectuant une vérification booléenne qui est toujours rapide. Le problème que je vois est la cohérence. Si certaines de vos instructions de débogage et d'informations sont encapsulées et d'autres non, ce n'est pas un style de code cohérent. De plus, plus tard, quelqu'un pourrait changer l'instruction de débogage pour inclure des chaînes de concaténation, ce qui est encore assez rapide. J'ai constaté que lorsque nous avons enveloppé la déclaration de débogage et d'informations dans une grande application et que nous l'avons profilée, nous avons économisé quelques points de pourcentage de performances. Pas beaucoup, mais assez pour que le travail en vaille la peine. J'ai maintenant quelques macros configurées dans IntelliJ pour générer automatiquement des instructions de débogage et d'informations encapsulées pour moi.

Javamann
la source
0

Je recommanderais d'utiliser l'option 2 de facto pour la plupart car ce n'est pas super cher.

Cas 1: log.debug ("une chaîne")

Case2: log.debug ("une chaîne" + "deux chaînes" + object.toString + object2.toString)

Au moment où l'un d'eux est appelé, la chaîne de paramètres dans log.debug (que ce soit CASE 1 ou Case2) DOIT être évaluée. C'est ce que tout le monde entend par «cher». Si vous avez une condition devant elle, 'isDebugEnabled ()', celles-ci n'ont pas besoin d'être évaluées, c'est là que les performances sont enregistrées.

Jolly1234
la source
0

Depuis 2.x, Apache Log4j a ce contrôle intégré, donc avoir isDebugEnabled()n'est plus nécessaire. Faites juste un debug()et les messages seront supprimés s'ils ne sont pas activés.

ha9u63ar
la source
-1

Log4j2 vous permet de formater les paramètres dans un modèle de message, semblable à String.format(), éliminant ainsi le besoin de faire isDebugEnabled().

Logger log = LogManager.getFormatterLogger(getClass());
log.debug("Some message [myField=%s]", myField);

Exemple de log4j2.properties simple:

filter.threshold.type = ThresholdFilter
filter.threshold.level = debug
appender.console.type = Console
appender.console.name = STDOUT
appender.console.layout.type = PatternLayout
appender.console.layout.pattern = %d %-5p: %c - %m%n
appender.console.filter.threshold.type = ThresholdFilter
appender.console.filter.threshold.level = debug
rootLogger.level = info
rootLogger.appenderRef.stdout.ref = STDOUT
André
la source