En log4j, ¿la comprobación de isDebugEnabled antes de iniciar sesión mejora el rendimiento?

Estoy usando Log4J en mi aplicación para iniciar sesión. Anteriormente estaba usando la llamada de depuración como:

Opción 1:

logger.debug("some debug text");

pero algunos enlaces sugieren que es mejor verificar isDebugEnabled()primero, como:

Opcion 2:

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

Entonces mi pregunta es " ¿La opción 2 mejora el rendimiento de alguna manera? ".

Porque, en cualquier caso, el marco Log4J tiene la misma verificación para debugEnabled. Para la opción 2, podría ser beneficioso si estamos usando múltiples declaraciones de depuración en un solo método o clase, donde el marco no necesita llamar al isDebugEnabled()método varias veces (en cada llamada); en este caso, llama al isDebugEnabled()método solo una vez, y si Log4J está configurado para depurar el nivel, en realidad llama al isDebugEnabled()método dos veces:

1. En caso de asignar valor a la variable debugEnabled, y
2. Realmente llamado por el método logger.debug ().

No creo que si escribimos múltiples logger.debug()declaraciones en método o clase y debug()método de llamada de acuerdo con la opción 1, entonces es una sobrecarga para el marco Log4J en comparación con la opción 2. Dado que isDebugEnabled()es un método muy pequeño (en términos de código), podría Ser un buen candidato para la línea.

En este caso particular, la opción 1 es mejor.

La declaración de protección (comprobación isDebugEnabled()) está ahí para evitar el cálculo potencialmente costoso del mensaje de registro cuando implica la invocación de los toString()métodos de varios objetos y la concatenación de los resultados.

En el ejemplo dado, el mensaje de registro es una cadena constante, por lo que dejar que el registrador lo descarte es tan eficiente como verificar si el registrador está habilitado, y disminuye la complejidad del código porque hay menos ramas.

Mejor aún es usar un marco de registro más actualizado donde las declaraciones de registro toman una especificación de formato y una lista de argumentos para ser sustituidos por el registrador, pero "perezosamente", solo si el registrador está habilitado. Este es el enfoque adoptado por slf4j .

Vea mi respuesta a una pregunta relacionada para obtener más información y un ejemplo de hacer algo como esto con log4j.

Dado que en la opción 1 la cadena del mensaje es una constante, no hay absolutamente ninguna ganancia en envolver la declaración de registro con una condición, por el contrario, si la declaración de registro está habilitada para la depuración, evaluará dos veces, una en el isDebugEnabled()método y una vez en debug()método. El costo de invocar isDebugEnabled()es del orden de 5 a 30 nanosegundos, lo que debería ser insignificante para la mayoría de los propósitos prácticos. Por lo tanto, la opción 2 no es deseable porque contamina su código y no proporciona ninguna otra ganancia.

El uso de isDebugEnabled()está reservado para cuando está creando mensajes de registro concatenando cadenas:

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

Sin embargo, en su ejemplo no hay ganancia de velocidad ya que solo está registrando una Cadena y no realiza operaciones como la concatenación. Por lo tanto, solo está agregando hinchazón a su código y haciendo que sea más difícil de leer.

Personalmente uso las llamadas de formato Java 1.5 en la clase String de esta manera:

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

Dudo que haya mucha optimización, pero es más fácil de leer.

Sin embargo, tenga en cuenta que la mayoría de las API de registro ofrecen un formato como este listo para usar: slf4j, por ejemplo, proporciona lo siguiente:

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

lo cual es aún más fácil de leer.

En Java 8, no tiene que usar isDebugEnabled()para mejorar el rendimiento.

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

Versión corta: también puede hacer la comprobación booleana isDebugEnabled ().

Motivos:
1- Si la lógica complicada / cadena concat. se agrega a su estado de depuración ya tendrá el cheque en su lugar.
2- No tiene que incluir selectivamente la declaración en las declaraciones de depuración "complejas". Todas las declaraciones se incluyen de esa manera.
3- Llamar a log.debug ejecuta lo siguiente antes de iniciar sesión:

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

Esto es básicamente lo mismo que llamar al registro. o gato isDebugEnabled ().

¡SIN EMBARGO! Esto es lo que piensan los desarrolladores de log4j (ya que está en su javadoc y probablemente debería seguirlo).

Este es el metodo

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

Este es el javadoc para ello

/**
*  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 otros han mencionado, usar la declaración de protección solo es realmente útil si crear la cadena es una llamada que consume mucho tiempo. Ejemplos específicos de esto son cuando la creación de la cadena desencadenará una carga lenta.

Vale la pena señalar que este problema se puede evitar utilizando Simple Logging Facade para Java o (SLF4J): http://www.slf4j.org/manual.html . Esto permite llamadas a métodos como:

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

Esto solo convertirá los parámetros pasados ​​en cadenas si la depuración está habilitada. SLF4J como su nombre lo indica es solo una fachada y las llamadas de registro se pueden pasar a log4j.

También podría fácilmente "rodar su propia versión" de esto.

Espero que esto ayude.

La opción 2 es mejor.

Per se no mejora el rendimiento. Pero asegura que el rendimiento no se degrada. Así es cómo.

Normalmente esperamos logger.debug (someString);

Pero generalmente, a medida que la aplicación crece, cambia muchas manos, especialmente los desarrolladores novatos, se puede ver

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

y similares.

Incluso si el nivel de registro está configurado en ERROR o FATAL, ¡la concatenación de cadenas ocurre! Si la aplicación contiene muchos mensajes de nivel DEBUG con concatenaciones de cadenas, entonces ciertamente requiere un impacto en el rendimiento, especialmente con jdk 1.4 o inferior. (No estoy seguro si las versiones posteriores de jdk internall hacen stringbuffer.append ()).

Es por eso que la Opción 2 es segura. Incluso las concatenaciones de cuerdas no suceden.

Al igual que @erickson, depende. Si mal no recuerdo, isDebugEnabledya está construido en el debug()método de Log4j.
Siempre que no esté haciendo algunos cálculos caros en sus declaraciones de depuración, como bucle en objetos, realizar cálculos y concatenar cadenas, en mi opinión, está bien.

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

sería mejor 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 una sola línea , uso un ternario dentro del mensaje de registro, de esta manera no hago la concatenación:

ej:

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

Hago:

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

Pero para múltiples líneas de código

ej.

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

Hago:

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

Dado que muchas personas probablemente están viendo esta respuesta cuando buscan log4j2 y casi todas las respuestas actuales no consideran log4j2 o los cambios recientes en él, es de esperar que conteste la pregunta.

log4j2 es compatible con los proveedores (actualmente su propia implementación, pero de acuerdo con la documentación, se planea utilizar la interfaz de proveedores de Java en la versión 3.0). Puede leer un poco más sobre esto en el manual . Esto le permite colocar costosas creaciones de mensajes de registro en un proveedor que solo crea el mensaje si se va a registrar:

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

Mejora la velocidad porque es común concatenar cadenas en el texto de depuración que es costoso, por ejemplo:

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

Desde la versión de Log4j2.4 (o slf4j-api 2.0.0-alpha1) es mucho mejor usar una API fluida (o compatibilidad con Java 8 lambda para el registro diferido ), compatible Supplier<?>con el argumento del mensaje de registro, que puede proporcionar lambda :

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

O con la API slf4j:

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

Si usa la opción 2, está haciendo una comprobación booleana que es rápida. En la opción uno, está haciendo una llamada al método (empujando cosas en la pila) y luego haciendo una verificación booleana que aún es rápida. El problema que veo es la consistencia. Si algunas de sus declaraciones de depuración e información están envueltas y otras no, no es un estilo de código consistente. Además, alguien más tarde podría cambiar la declaración de depuración para incluir cadenas concatenadas, que todavía es bastante rápido. Descubrí que cuando completamos la declaración de depuración e información en una aplicación grande y la perfilamos, ahorramos un par de puntos porcentuales en rendimiento. No mucho, pero lo suficiente como para que valga la pena el trabajo. Ahora tengo un par de macros configuradas en IntelliJ para generar automáticamente declaraciones de información y depuración envueltas para mí.

Recomendaría usar la opción 2 de facto para la mayoría, ya que no es súper cara.

Caso 1: log.debug ("una cadena")

Caso2: log.debug ("una cadena" + "dos cadenas" + object.toString + object2.toString)

En el momento en que se llama a cualquiera de estos, la cadena de parámetros dentro de log.debug (ya sea CASO 1 o Caso2) TIENE que ser evaluada. Eso es lo que todos quieren decir con "caro". Si tiene una condición anterior, 'isDebugEnabled ()', no es necesario evaluarlas, que es donde se guarda el rendimiento.

A partir de 2.x, Apache Log4j tiene esta verificación incorporada, por lo que isDebugEnabled()ya no es necesario tenerla . Simplemente haga una debug()y los mensajes serán suprimidos si no están habilitados.

Log4j2 le permite formatear parámetros en una plantilla de mensaje, similar a String.format(), eliminando así la necesidad de hacerlo isDebugEnabled().

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

Muestra simple log4j2.properties:

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