¿Qué está realmente haciendo log4j cuando activamos o desactivamos algunos lugares de registro?

Question

Sabemos que podemos configurar log4j para desactivar el inicio de sesión en lugares específicos (clase o paquete en Java) a través de sus propiedades/archivo de configuración. Mis preguntas son seguidas:

1. ¿Qué está haciendo realmente log4j para esas banderas?
2. ¿Todavía se llama a la instrucción de registro en log4j pero no se está escribiendo en el archivo o la consola debido a esa marca? entonces todavía tienen impacto en el rendimiento?
3. ¿Es como #ifdef en C++ que surte efecto en el momento de la compilación y puede limitar el impacto en el rendimiento?

gracias,

Answer 1

Sí, todavía se ejecutan las instrucciones de registro. Esto es por qué es un buen patrón para comprobar el nivel de registro en primer lugar: algo así como

if (log.isInfoEnabled()) { 
    log.info("My big long info string: " + someMessage); 
} 

Esto es para evitar que la reasignación de espacio para la información String cuando el nivel de registro no soporta INFO declaraciones.

No es nada como #ifdef - #ifdef es una directiva de compilación, mientras que las configuraciones de Log4J se procesan en tiempo de ejecución.

Editar: Odio que me caduquen debido a la ignorancia, así que aquí hay un artículo que respalda mi respuesta.

De http://surguy.net/articles/removing-log-messages.xml:

En Log4J, si se registra un mensaje en nivel de depuración, y el Appender de corriente está ajustado a registrar sólo los mensajes de nivel INFO y por encima, entonces el mensaje no lo hará se mostrará. La penalización de rendimiento por llamar al método de registro es mínima: unos pocos nanosegundos. Sin embargo, puede tomar más tiempo para evaluar los argumentos para el método de registro . Por ejemplo:

logger.debug ("El objeto grande es " + largeObject.toString());

Evaluación de largeObject.toString() puede ser lenta, y se evalúa antes la llamada al registrador, por lo que el registrador no se puede evitar que se está evaluando, a pesar de que no va a utilizar.

Editar 2: desde el propio manual de log4j (http://logging.apache.org/log4j/1.2/manual.html):

El usuario debe ser consciente de los siguientes problemas de rendimiento.

1. Rendimiento de registro cuando el registro está desactivado. Cuando el registro está desactivado por completo o solo para un conjunto de niveles, el costo de una solicitud de registro consiste en una invocación de método más una comparación entera. En una máquina Pentium II de 233 MHz, este costo generalmente se encuentra en el rango de 5 a 50 nanosegundos.

   Sin embargo, la invocación del método implica el costo "oculto" de la construcción del parámetro.

   Por ejemplo, para un gato logger, escritura,

   logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); 
   

   incurre en el costo de construir el parámetro de mensaje, es decir la conversión de tanto número entero i y la entrada [i] en una cadena, y concatenación de cadenas intermedias, independientemente de si el mensaje se registrará o no. Este costo de construcción de parámetros puede ser bastante alto y depende del tamaño de los parámetros involucrados.

   Para evitar el parámetro de coste de construcción de escritura:

   if(logger.isDebugEnabled() { 
       logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); 
   } 
   

   Esto no incurrirá en el costo de la construcción parámetro si la depuración está desactivada. Por otro lado, si el registrador está habilitado para la depuración, incurrirá en el doble del costo de evaluar si el registrador está habilitado o no: una vez en DebugEnabled y una vez en la depuración. Esta es una carga indirecta insignificante porque la evaluación de un registrador demora aproximadamente el 1% del tiempo que lleva registrar realmente.

Answer 2

1. log4j procesará la declaración de registro, y comprobar para ver si el registrador en particular está habilitado en el nivel de registro en particular. Si no es así, la declaración no se registrará.

2. Estas comprobaciones son significativamente menos costosas que la escritura real en el disco (o consola), pero todavía tienen un impacto.

3. no, Java tiene ningún concepto como #ifdef (fuera de la caja de todos modos, hay precompiladores java por ahí)

Answer 3

me encontré una referencia sencilla para poner a prueba.

for (int j = 0; j < 5; j++) { 
     long t1 = System.nanoTime()/1000000; 
     int iterations = 1000000; 
     for (int i = 0; i < iterations; i++) { 
      int test = i % 10; 
      log.debug("Test " + i + " has value " + test); 
     } 
     long t2 = System.nanoTime()/1000000; 
     log.info("elapsed time: " + (t2 - t1)); 

     long t3 = System.nanoTime()/1000000; 
     for (int i = 0; i < iterations; i++) { 
      int test = i % 10; 
      if (log.isDebugEnabled()) { 
       log.debug("Test " + i + " has value " + test); 
      } 
     } 
     long t4 = System.nanoTime()/1000000; 
     log.info("elapsed time 2: " + (t4 - t3)); 
    } 

elapsed time: 539 
elapsed time 2: 17 
elapsed time: 450 
elapsed time 2: 18 
elapsed time: 454 
elapsed time 2: 19 
elapsed time: 454 
elapsed time 2: 17 
elapsed time: 450 
elapsed time 2: 19 

Con 1.6.0_18, lo cual me sorprendió ya que pensé que la línea habría impedido esto. Tal vez Java 7 con análisis de escape lo haga.

Sin embargo, todavía no envolvería declaraciones de depuración en una cláusula if a menos que las mejoras de tiempo del orden de medio microsegundo lleguen a ser importantes.