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

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.

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.

É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.

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.

En Java 8, vous n'avez pas besoin d'utiliser isDebugEnabled() pour améliorer les performances.

https://logging.apache.org/log4j/2.0/manual/api.html#Java_8_lambda_support_for_lazy_logging

import java.util.logging.Logger;
...
Logger.getLogger("hello").info(() -> "Hello " + name);

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.
*   */

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.

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.

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());
}

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());
    }
}

É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());

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);
}

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 : {}");

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.

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.

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.

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