Log4j: ¿está sincronizado para llamadas multiproceso?

Nos encontramos con un problema interesante que notamos al hacer pruebas de estrés de nuestro sistema. Estamos usando log4j (en JBOSS) muy fuertemente para nuestro registro. Aquí es un ejemplo de algunos ingenuos que la tala AVELog4j: ¿está sincronizado para llamadas multiproceso?

void someFunction() 
{ 
Log.info("entered some function"); 
... 

Log.info("existed some function"); 
}

Ahora lo interesante que notamos es que si lanzamos 100 hilos en contra de esta función; las llamadas Log.info() se bloquean por hilo ... lo que significa que el hilo 2 está esperando que hilo1 termine la llamada "Log.info". En caso de Thread 100; termina esperando bastante tiempo. Estamos usando un registrador de archivos nativo.

¿Es esto un problema conocido?

Fuente

2012-02-18 shergill

'Log' es una clase? ¿O un objeto de tipo 'Logger'? – Tudor

Log es un objeto de tipo logger obtenido de Loggerfactory – shergill

Ok gracias. Sólo quería asegurarme. Estaba yendo a través del código fuente de 'Logger' y encontré que de hecho hay una sección' synchronized' allí. – Tudor

Lo que es posible que desee es registro asíncrono, consulte este artículo sobre cómo lograr que:

Asynchronous logging with log4j

También, considere el uso de los niveles de registro adecuados. Las declaraciones entered... y exi(s)ted... generalmente deben registrarse en el nivel TRACE, lo que puede ser útil al depurar (luego, configure configure log4j para que también se registre en el nivel TRACE). En una configuración de producción, es posible que desee indicarle a log4j que solo inicie sesión desde el nivel INFO o DEBUG, evitando acciones de registro innecesarias.

Ver también esta cuestión en el desempeño de log4j:

log4j performance

Fuente

2012-02-18 18:34:42

El enlace no funciona –

Gracias, se actualizó el enlace –

Log4J tiene que ser sincronizados, de lo contrario se podría ver los mensajes de registro intercalados y confusos en su archivo. Pero al menos en Logback, solo los appenders están sincronizados, no el mensaje de registro completo (por lo que el cálculo del nivel de registro efectivo, el mensaje de registro, etc. tiene múltiples subprocesos).

Sin embargo, incluso si se eliminara la sincronización, la E/S sería el cuello de botella ya que es intrínsecamente de un solo subproceso. Por lo tanto, considere reducir la cantidad de registros, ya que es el acceso al archivo el que es lento, no Log4J.

También le puede interesar AsyncAppender para poner en cola mensajes de registro en un hilo único y diferente.

Fuente

2012-02-18 18:36:10

+1 - una cosa que creo que vale la pena mencionar es el intercambio con enfoques asíncronos; no está garantizado que todo el registro haya llegado al disco en el caso de un bloqueo del proceso o del sistema. –

No estoy seguro de entender el AsyncAppender. ¿No es la tala realmente 'asynchornous' ... lo que significa que está sucediendo en un hilo separado? Significado en mi ejemplo anterior; cuando llamo "Log.Info (" abc "); en realidad, no se escribe en el archivo de inmediato ... parece estar retrasado? – shergill

@shegill, sí, está retrasado. Está almacenado en el AsyncAppender antes de que se cargue. se envía a los delegados adjuntos. Esta es la razón de la advertencia de Brian sobre la pérdida de mensajes de registro en el caso de un bloqueo del sistema, corre el mismo peligro si no tiene sus apéndices enrasados en el disco después de cada mensaje de registro – Victor

Otros ya se han sugerido alternativas, he estado cavando a través del código fuente y de hecho hay una sección synchronized:

public void info(Object message) { 
    if(repository.isDisabled(Level.INFO_INT)) 
     return; 
    if(Level.INFO.isGreaterOrEqual(this.getEffectiveLevel())) 
     forcedLog(FQCN, Level.INFO, message, null); 
} 

... 

protected void forcedLog(String fqcn, Priority level, Object message, Throwable t) { 
    callAppenders(new LoggingEvent(fqcn, this, level, message, t)); 
} 

... 

public void callAppenders(LoggingEvent event) { 
    int writes = 0; 

    for(Category c = this; c != null; c=c.parent) { 
     // Protected against simultaneous call to addAppender, removeAppender,... 
     synchronized(c) { 
      if(c.aai != null) { 
       writes += c.aai.appendLoopOnAppenders(event); 
      } 
      if(!c.additive) { 
       break; 
      } 
     } 
    } 

    if(writes == 0) { 
     repository.emitNoAppenderWarning(this); 
    } 
}

Fuente

2012-02-18 23:46:35 Tudor

Sí, log4j utiliza syncronyzation multihilo. Y no perfectamente, a veces.

Tuvimos una cierta degradación del rendimiento causada por la contención de los bloqueos log4j e incluso los interbloqueos con el uso del método complejo toString().

Véase https://issues.apache.org/bugzilla/show_bug.cgi?id=24159 y https://issues.apache.org/bugzilla/show_bug.cgi?id=41214#c38, por ejemplo.

Más detalles en mi otra respuesta: Production settings file for log4j?

supongo que esto es una de las razones de la existencia logback y cambiar a logmanager costumbre desde JBoss AS 6.

Fuente

2012-02-20 16:23:15 Vadzim

-4

De acuerdo con las respuestas anteriores. Uno de los primeros pasos de mejora del rendimiento en cualquier aplicación es reducir el nivel de registro y hacer que descargue menos registros. Los desarrolladores de aplicaciones deben ser diligentes en el uso de los niveles correctos de registro. El registro tiene un gran impacto en el rendimiento debido a la E/S, así como la sincronización, especialmente cuando los objetos del registrador son estáticos y se comparten entre varios subprocesos.

Fuente

2012-10-21 00:49:52 vishr

Log4j: ¿está sincronizado para llamadas multiproceso?

Respuesta

Cuestiones relacionadas