Introducción a SLF4J

Escribo esto porque hace poco hice unas pruebas para comparar el performance de SLF4J contra Jakarta Commons Logging.

Llevaba ya tiempo usando JCL, un framework para logging que tiene la ventaja de ser una capa de abstracción sobre otros frameworks; es decir, se puede programar usando el API de JCL y en deployment se utiliza Log4J por ejemplo para hacer realmente el trabajo de los logs, o bien usar java.util.logging sin tener que cambiar una sola línea de código (JCL auto-detecta Log4J y si no está, se usa java.util.logging). Se pueden hacer interfaces para usar otros frameworks de logging.

SLF4J (Simple Logging Framework for Java) es muy similar: es simplemente una API que en tiempo de ejecución se apoya en algún framework de logging como Log4J, java.util.logging, etc. Su arquitectura interna es distinta en la manera que usa el framework real para logging: debe tenerse en el classpath el JAR que define el API junto con una sola implementación de backend, por ejemplo para Log4J.

Para compilar código que usa el API, solamente es necesario tener el JAR del API de SLF4J en el classpath. Los jars de SLF4J para usar una librería de logging solamente son necesarios para tiempo de ejecución.

SLF4J incluso tiene un JAR muy útil que contiene clases con el mismo nombre y métodos del API de JCL, pero utilizan internamente el API de SLF4J. De este modo se puede hacer una migración gradual de JCL a SLF4J, usar frameworks que requieren JCL (como Spring, o cualquier otra librería de Jakarta Commons).

En las pruebas que hice, noté que realmente SLF4J es más rápido que JCL. Ambas pruebas fueron usando Log4J para hacer el verdadero trabajo de logging; sin embargo por alguna razón es más rápido SLF4J. La diferencia en tiempo al principio no fue mucha; sin embargo, el cambio solamente había consistido en usar org.slf4j.Logger en vez de org.apache.commons.logging.Log. Muchas llamadas a debug, info, etc tenían parámetros, que yo resolvía usando String.format(), por ejemplo así:

log.debug(String.format("Procesando %d registros", numRows));

log.debug(String.format("Dato 1: %s Dato 2: %d Dato 3: %s", d1, d2, d3));


try {
  //codigo que lanza excepcion
} catch (SomeException ex) {
  log.error(String.format("Codigo: %d Mensaje: %s", d1, d2), ex);
}

Es mucho más rápido y eficiente usar String.format() que concatenar las partes del mensaje usando +. Pero SLF4J además tiene su propio soporte para este tipo de mensajes, que son bastante comunes (normalmente en un log quieres dejar información útil y muy específica para el evento que estás registrando). El soporte tiene 3 métodos distintos: uno que recibe un parámetro adicional, otro que recibe dos parámetros adicionales, y uno que recibe un arreglo de parámetros (para cuando necesitas 3 o más datos). De modo que el código queda así:

log.debug("Procesando {} registros", numRows);

log.debug("Dato 1: {} Dato 2: {} Dato 3: {}", new Object[]{ d1, d2, d3 });


try {
  //codigo que lanza excepcion
} catch (SomeException ex) {
  log.error(String.format("Codigo: %d Mensaje: %s", d1, d2), ex);
}

La implementación de SLF4J para crear la cadena final, sustituyendo los {} por los parámetros recibidos en el método, es más rápido que el String.format(), probablemente porque es más simple que este último debido a que no acepta por el momento formatos como %04x, %5.2f, %-5s, etc. Sin embargo, si se compara hacer log.debug(String.format("%s", x)) contra log.debug("{}", x), el segundo es más rápido.

La manera en que lo probé fue haciendo 10mil llamadas a un método, luego 10mil llamadas a otro, y tomar el tiempo. La diferencia no es mucha: SLF4J termina entre 50 y 300 más rápido que JCL, ambos usando String.format(); sin embargo al cambiar la prueba de SLF4J para usar los {}, la diferencia de tiempo sube de 100 a 600 milisegundos.

Otra ventaja de usar los {} en SLF4J es que el framework primero revisa si el nivel de log solicitado (trace, debug, info, warn, o error) está activo, y solamente crea la cadena con los parámetros recibidos de ser necesario. Lo cual significa que ya no es necesario llenar el código de if (log.isDebugEnabled()) para imprimir mensajes en el log, porque SLF4J lo hace internamente. Con JCL hay que revisar primero, porque la llamada posterior al log incluirá un String.format() que no hay que llamar de forma innecesaria.

Desafortunadamente, no hay métodos que reciban parámetros adicionales cuando se va a imprimir una excepción. Espero que pronto agreguen métodos que primero reciban la excepción y después reciban parámetros para poner en el mensaje, así como una versión de SLF4J que sirva en Java 5 con varargs para no tener que crear el arreglo de objetos en nuestro código.

Anexo el código que hice para estas pruebas:

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;

public class JclBenchmark {

public static final Log log = LogFactory.getLog(JclBenchmark.class);

public static void main(String[] args) {
        long ini = System.currentTimeMillis();
        for (int i = 0; i < 10000; i++) {
                log.info(String.format("Hora %d i es %d", System.currentTimeMillis(), i));
        }
        long fin = System.currentTimeMillis();
        System.out.printf("TARDA %d milis%n", fin-ini);
}

}

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Slf4jBenchmark {

public static final Logger log = LoggerFactory.getLogger(Slf4jBenchmark.class);

public static void main(String[] args) {
        long ini = System.currentTimeMillis();
        for (int i = 0; i < 10000; i++) {
                log.info("Hora {} i es {}", System.currentTimeMillis(), i);
        }
        long fin = System.currentTimeMillis();
        System.out.printf("TARDA %d milis%n", fin-ini);
}

}

Comentarios

Opciones de visualización de comentarios

Seleccione la forma que prefiera para mostrar los comentarios y haga clic en «Guardar las opciones» para activar los cambios.
Imagen de luxspes

Excelente ahora prueba logback

Si, SLF4J es, en mi opinión, la mejor fachada para bitacorizacion que hay para Java en este momento (es patético que siendo una idea tan simple, JUL no haya sido creado con la misma idea). Ahora solo te falta probar logback (de Ceki Gülcü el mismo autor que log4j y slf4j) para que sustituyas a log4j como el encargado de hacer el verdadero trabajo de logging.

El manual de logback es bastante completo y cuenta con todo el poder con el que contaba log4j, mas varios trucos nuevos, por ejemplo, enviar correos cada vez que se produce un logging de nivel error con el stack trace de la excepcion en ese momento es tan fácil como ajustar el archivo logback.xml e incluir los .jar de javax.mail en tu aplicación.

Imagen de ezamudio

logback

Le echaré un ojo. Al fin que ya es el puro backend y no cambian las llamadas al API, que fue lo que estuvo medio duro de migrar (cambiar todas las referencias a JCL por referencias a SLF4J y sigo en proceso de aprovechar los logs con {} para disminuir el tiempo de generación de esos mensajes)

Imagen de ezamudio

Logback

OK ya probé el performance de Logback, simplemente corriendo la clase que puse aquí de Slf4jBenchmark primero con Log4J como backend y luego con logback... en promedio Logback tarda el 80% del tiempo en hacer los mismos logs que Log4J, así que sí hay algo de ganancia en performance. Por el momento en mis sistemas en producción tengo el AsyncAppender de Log4J para que no se afecte el performance del sistema haciendo logs, pero si Logback tiene algo parecido pues lo probaré en algún momento. Solamente me preocupa un poco el número de versión (0.9), no sé qué considera el autor que le falta al proyecto para estar completo y tener versión 1.

Desafortunadamente, no hay

Desafortunadamente, no hay métodos que reciban parámetros adicionales cuando se va a imprimir una excepción. Espero que pronto agreguen métodos que primero reciban la excepción y después reciban parámetros para poner en el mensaje, así como una versión de SLF4J que sirva en Java 5 con varargs para no tener que crear el arreglo de objetos en nuestro código.

Desde la versión 1.6.0 es posible, siempre y cuando la excepción sea el último parámetro.

Imagen de ezamudio

así es

Ya hay versiones variádicas de los métodos desde la versión 1.6, sin embargo no sé por qué dejaron las versiones anteriores y ahora eso da problemas en Scala y Groovy, que tienes que llamar el método como log.info("bla", Array(a,b,c):_*) (o algo así era).

Imagen de apolonioluis

suspender los mensjes

tengo una libreria de terceros que me da muchos mensajes tipo info, ya busque y no supe como suspender esos mensajes.

alguien sabe de slf4j ?

Imagen de ezamudio

backend

Qué backend usas? Porque para filtrar los mensajes por su nivel o por su categoría, necesitas ir directo al backend, no a slf4j.

Imagen de apolonioluis

backend?

gracias por su ayuda,

En esta imagen se ve la estructura de la libreria Yank Jdbc:

http://s30.postimg.org/vq347tnmp/yank.jpg

donde localizo el backend?

Imagen de ezamudio

logback

Por ahí veo logback. Es probable que estés usando logback como backend. Entonces los filtros que necesitas, van directo en la configuración de logback.