No log4j, a verificação de isDebugEnabled antes do registro melhora o desempenho?

Estou usando o Log4J no meu aplicativo para log. Anteriormente, eu estava usando a chamada de depuração como:

Opção 1:

logger.debug("some debug text");

mas alguns links sugerem que é melhor verificar isDebugEnabled()primeiro, como:

Opção 2:

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

Portanto, minha pergunta é " A opção 2 melhora o desempenho de alguma maneira? ".

Porque, em qualquer caso, a estrutura Log4J tem a mesma verificação para debugEnabled. Para a opção 2, pode ser benéfico se estivermos usando várias instruções de depuração em um único método ou classe, em que a estrutura não precisa chamar o isDebugEnabled()método várias vezes (em cada chamada); nesse caso, ele chama o isDebugEnabled()método apenas uma vez e, se o Log4J estiver configurado para o nível de depuração, na verdade, ele chama o isDebugEnabled()método duas vezes:

1. No caso de atribuir valor à variável debugEnabled, e
2. Realmente chamado pelo método logger.debug ().

Eu não acho que se escrevermos várias logger.debug()instruções no método ou classe e chamar o debug()método de acordo com a opção 1, isso será uma sobrecarga para o framework Log4J em comparação com a opção 2. Como isDebugEnabled()é um método muito pequeno (em termos de código), ele pode ser um bom candidato para inlining.

Nesse caso em particular, a opção 1 é melhor.

A declaração de guarda (checando isDebugEnabled() ) existe para impedir o cálculo potencialmente caro da mensagem de log quando envolve a invocação dos toString()métodos de vários objetos e a concatenação dos resultados.

No exemplo dado, a mensagem de log é uma cadeia constante, portanto, deixar o logger descartá-la é tão eficiente quanto verificar se o logger está ativado e diminui a complexidade do código porque há menos ramificações.

Melhor ainda é usar uma estrutura de log mais atualizada, na qual as instruções de log adotam uma especificação de formato e uma lista de argumentos a serem substituídos pelo criador de logs - mas "preguiçosamente", apenas se o criador de logs estiver ativado. Esta é a abordagem adotada pelo slf4j .

Veja minha resposta a uma pergunta relacionada para obter mais informações e um exemplo de como fazer isso com o log4j.

Como na opção 1 a cadeia de mensagens é uma constante, não há absolutamente nenhum ganho em agrupar a instrução de log com uma condição; pelo contrário, se a instrução de log estiver ativada para depuração, você avaliará duas vezes, uma vez no isDebugEnabled()método e outra em debug()método. O custo da chamada isDebugEnabled()é da ordem de 5 a 30 nanossegundos, o que deve ser insignificante para os propósitos mais práticos. Portanto, a opção 2 não é desejável, pois polui seu código e não oferece outros ganhos.

O uso de isDebugEnabled()é reservado para quando você estiver criando mensagens de log concatenando Strings:

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

No entanto, no seu exemplo, não há ganho de velocidade, pois você está apenas registrando uma String e não executando operações como concatenação. Portanto, você está apenas adicionando inchaço ao seu código e dificultando a leitura.

Pessoalmente, uso as chamadas no formato Java 1.5 na classe String, desta forma:

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

Duvido que haja muita otimização, mas é mais fácil de ler.

Observe, porém, que a maioria das APIs de log oferece formatação assim: o slf4j, por exemplo, fornece o seguinte:

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

o que é ainda mais fácil de ler.

No Java 8, você não precisa usar isDebugEnabled()para melhorar o desempenho.

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

Versão curta: Você também pode fazer a verificação booleana isDebugEnabled ().

Razões:
1- Se a lógica / string complicada for concat. é adicionado à sua instrução de depuração, você já terá a verificação no local.
2- Você não precisa incluir seletivamente a instrução nas instruções de depuração "complexas". Todas as instruções são incluídas dessa maneira.
3- Chamar log.debug executa o seguinte antes do log:

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

Isso é basicamente o mesmo que chamar log. ou gato. isDebugEnabled ().

CONTUDO! É isso que os desenvolvedores do log4j pensam (como está no javadoc e você provavelmente deve seguir em frente).

Este é o método

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

Este é o javadoc para ele

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

Como outros usuários mencionaram, usar a declaração de guarda só é realmente útil se a criação da string for uma chamada demorada. Exemplos específicos disso são quando a criação da string acionará um carregamento lento.

Vale ressaltar que esse problema pode ser solucionado com o Simple Logging Facade for Java ou (SLF4J) - http://www.slf4j.org/manual.html . Isso permite chamadas de método como:

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

Isso só converterá os parâmetros passados ​​em strings se a depuração estiver ativada. SLF4J, como o próprio nome sugere, é apenas uma fachada e as chamadas de log podem ser passadas para o log4j.

Você também pode facilmente "rodar o seu próprio" versão disso.

Espero que isto ajude.

A opção 2 é melhor.

Por si só, não melhora o desempenho. Mas garante que o desempenho não diminua. Aqui está como.

Normalmente esperamos logger.debug (someString);

Mas geralmente, conforme o aplicativo cresce, muda muitas mãos, especialmente para desenvolvedores iniciantes, você pode ver

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

e similar.

Mesmo se o nível do log estiver definido como ERROR ou FATAL, a concatenação de cadeias acontecerá! Se o aplicativo contiver muitas mensagens no nível DEBUG com concatenações de cadeias, certamente será necessário um impacto no desempenho, especialmente no jdk 1.4 ou abaixo. (Não tenho certeza se as versões posteriores do jdk internall executam qualquer stringbuffer.append ()).

É por isso que a opção 2 é segura. Até as concatenações de strings não acontecem.

Como @erickson, depende. Se bem me lembro, isDebugEnabledjá é construir no debug()método de Log4j.
Contanto que você não esteja fazendo alguns cálculos caros em suas instruções de depuração, como loop em objetos, faça cálculos e concatene seqüências de caracteres, você está bem na minha opinião.

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

seria melhor como

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

Para uma única linha , eu uso um ternário dentro da mensagem de log. Dessa maneira, não faço a concatenação:

ej:

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

Eu faço:

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

Mas para várias linhas de código

ej.

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

Eu faço:

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

Como muitas pessoas provavelmente estão visualizando essa resposta ao procurar pelo log4j2 e quase todas as respostas atuais não consideram o log4j2 ou alterações recentes, esperamos que isso responda à pergunta.

O log4j2 suporta os fornecedores (atualmente sua própria implementação, mas de acordo com a documentação, está planejado usar a interface de fornecedor do Java na versão 3.0). Você pode ler um pouco mais sobre isso no manual . Isso permite que você coloque a criação cara de mensagens de log em um fornecedor, que só cria a mensagem se for registrada:

LogManager.getLogger().debug(() -> createExpensiveLogMessage());

Melhora a velocidade porque é comum concatenar seqüências de caracteres no texto de depuração, o que é caro, por exemplo:

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

Desde a versão Log4j2.4 (ou slf4j-api 2.0.0-alpha1), é muito melhor usar API fluente (ou suporte Java 8 lambda para log lento ), suporte Supplier<?>para argumento de mensagem de log, que pode ser fornecido pelo lambda :

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

OU com a API slf4j:

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

Se você usa a opção 2, está fazendo uma verificação booleana que é rápida. Na opção um, você está fazendo uma chamada de método (pressionando coisas na pilha) e depois fazendo uma verificação booleana que ainda é rápida. O problema que vejo é consistência. Se algumas de suas instruções de depuração e informação estão agrupadas e outras não, não é um estilo de código consistente. Além disso, alguém mais tarde poderia alterar a instrução de depuração para incluir seqüências de caracteres concatenadas, o que ainda é bastante rápido. Descobri que, quando agrupamos as instruções de depuração e informações em um aplicativo grande e criamos um perfil, economizamos alguns pontos percentuais no desempenho. Não muito, mas o suficiente para fazer valer o trabalho. Agora, tenho algumas configurações de macros no IntelliJ para gerar automaticamente instruções de depuração e informações agrupadas para mim.

Eu recomendaria usar a Opção 2 como de fato para a maioria, pois não é muito caro.

Caso 1: log.debug ("uma sequência")

Case2: log.debug ("uma cadeia" + "duas cadeias" + object.toString + object2.toString)

No momento em que um desses itens é chamado, a sequência de parâmetros no log.debug (seja CASE 1 ou Case2) TEM QUE ser avaliada. É isso que todo mundo quer dizer com 'caro'. Se você tiver uma condição anterior, 'isDebugEnabled ()', não será necessário avaliar qual é o local onde o desempenho é salvo.

A partir do 2.x, o Apache Log4j possui essa verificação incorporada, portanto, isDebugEnabled()não é mais necessário. Basta fazer um debug()e as mensagens serão suprimidas se não estiverem ativadas.

O Log4j2 permite formatar parâmetros em um modelo de mensagem, semelhante a String.format(), eliminando assim a necessidade isDebugEnabled().

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

Amostra log4j2.properties simples:

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