2010-10-13 21 views
39

He leído un montón de mensajes y documentos (en este sitio y en otros lugares) que señalan que el patrón recomendado para el registro SFL4J es:¿Por qué no se recomienda llamar a LoggerFactory.getLogger (...) cada vez?

public class MyClass { 
    final static Logger logger = LoggerFactory.getLogger(MyClass.class); 

    public void myMethod() { 
     //do some stuff 
     logger.debug("blah blah blah"); 
    } 
} 

Mi jefe prefiere que sólo tiene que utilizar un envoltorio para interceptar llamadas de registro y evitar la caldera código de la placa para declarar el registrador en cada clase:

public class MyLoggerWrapper { 
    public static void debug(Class clazz, String msg){ 
     LoggerFactory.getLogger(clazz).debug(msg)); 
    } 
} 

y simplemente usarlo como esto:

public class MyClass { 

    public void myMethod() { 
     //do some stuff 
     MyLoggerWrapper.debug(this.getClass(), "blah blah blah"); 
    } 
} 

presumo crear instancias de un registrador cada vez que ingresamos es algo costoso, pero no he podido encontrar ningún documento que respalde esa suposición. Además, dice que seguramente el marco (LogBack o Log4J aún estamos decidiendo) "almacenará en caché" los registradores y también que, en cualquier caso, los servidores están funcionando muy por debajo de su capacidad por lo que no es un problema.

¿Alguna ayuda que indique posibles problemas con este enfoque?

+2

Otro punto: sus líneas de registro se vuelven feas con el método de su jefe, ya que la sintaxis de registro correcta es "MyLoggerWrapper.debug (MyClass.class," blah blah blah ");" –

+0

Gracias Benoit, eso es lo que pretendía mostrar, pero en el apuro por publicar hice un error tipográfico. Es solo un ejemplo, pero usaríamos algo como: MyLoggerWrapper.debug (esto.getClass(), "blah") – danirod

+0

pero con la importación estática, tiene una buena depuración (...) :) – Guillaume

Respuesta

3

No, aparte de ensuciar la pila de llamadas. Eso interrumpe los métodos que le permiten ver el nombre del método y la clase del código que realiza el registro.

Puede considerar echar un vistazo al contenedor web Jetty que contiene su propia abstracción que se basa en slf4j. Muy agradable.

11

Los objetos del registrador seguramente se vuelven a usar, por lo que no se producirán instancias adicionales de ninguna manera. El mayor problema que veo es que su número de información de archivo/línea será inútil, ya que el registrador siempre registrará fielmente que cada mensaje se ha emitido desde la clase LoggerWrapper, línea 12 :-(

otoh SLF4J ya es una fachada de envoltura para ocultar el marco de registro específico utilizado, lo que le permite cambiar libremente entre diferentes implementaciones de registro. Por lo tanto, no veo ningún sentido ocultarlo detrás de otro contenedor.

+3

debe señalar que incluir el número de línea en la salida de registro es tremendamente slow –

+1

También debe señalar que el nombre de la clase también se transfiere para identificar el registrador que se utilizará (en el ejemplo anterior). Por lo tanto, tu primer punto está resuelto. – Noremac

+0

@Noremac, es suficiente, el nombre de la clase se registrará correctamente. Sin embargo, sospecho fuertemente que el número de línea seguirá siendo incorrecto. –

28

Aquí hay un problema obvio con este enfoque: los mensajes de cadena se construirán en cada llamada al debug(), no hay una manera obvia de usar una cláusula de guardia con su envoltorio.

El lenguaje estándar con log4j/commons-logging/slf4j es utilizar una cláusula de protección tales como:

if (log.isDebugEnabled()) log.debug("blah blah blah"); 

Con el propósito de que si el nivel DEBUG no está habilitado para el registrador, el compilador puede evitar la concatenación de juntas por más tiempo cuerdas puede enviarla:

if (log.isDebugEnabled()) log.debug("the result of method foo is " + bar 
    + ", and the length is " + blah.length()); 

Ver "What is the fastest way of (not) logging?" in the SLF4J o log4j FAQ.

Recomendaría en contra del "envoltorio" que sugiere su jefe. Una biblioteca como slf4j o commons-logging ya es una fachada alrededor de la implementación de registro subyacente real utilizada. Además, cada invocación del registrador se convierte en mucho más largo - comparar lo anterior con

MyLoggerWrapper.debug(Foo.class, "some message"); 

Este es el tipo de "envoltura" trivial y sin importancia y la ofuscación que sirve a ningún propósito real aparte de la adición de capas de rodeos y ugly- fying tu código. Creo que su jefe puede encontrar problemas más importantes sobre los que obsesionarse.

+6

+1 para mencionar las cláusulas de guardia: es un punto importante. –

+3

Bueno, él es más como el líder del equipo/programador principal ;-) La cláusula de guardia ya se ha cuidado utilizando mensajes parametrizados -como se explica en su enlace y otros documentos que he leído- solo implementamos los métodos necesarios en el contenedor según sea necesario. Estoy de acuerdo con la fealdad de las llamadas de registro de wrapper(), pero aún no estoy convencido por ninguna de las respuestas aquí de que esto sea peor que la creación de instancias de registrador en cada clase que es un dolor en el cuello y algo feo también. – danirod

+5

No estoy seguro de que esté de acuerdo en que una línea de código por clase para hacer 'logger Logger estático final = LoggerFactory.getLogger (MyClass.class)' es tan feo. Usando su IDE de elección, es fácil encontrar una plantilla/macro simple para que pueda agregar este fragmento al archivo en solo unas pocas teclas. Sin embargo, la belleza está en el ojo del espectador ... –

10

Las llamadas repetidas a LoggerFactory.getLogger(clazz) no deben dar como resultado un nuevo objeto Logger cada vez. Pero eso no significa que las llamadas sean gratuitas. Si bien el comportamiento real depende del sistema de registro detrás de la fachada, es muy probable que cada getLogger requiera una búsqueda en una estructura de datos simultánea o sincronizada para buscar una instancia preexistente.

Si su aplicación hace muchas llamadas a su método MyLoggerWrapper.debug, todo esto puede sumar un golpe de rendimiento significativo. Y en una aplicación de subprocesos múltiples, podría ser un cuello de botella de concurrencia.

Otros temas mencionados por otras respuestas también son importantes:

  • Su aplicación ya no podrá utilizar logger.isDebugEnabled() para reducir al mínimo los gastos generales, cuando se desactiva la depuración.
  • La clase MyLoggerWrapper oscurece los nombres de las clases y los números de línea de las llamadas de depuración de su aplicación.
  • El código que usa MyLoggerWrapper probablemente será más detallado si realiza múltiples llamadas al registrador. Y la verbosidad estará en el área donde más impacte la legibilidad; es decir, en los métodos que hacen cosas que necesitan registro.

Por último, esto es simplemente "no es la forma en que se hace".


1 - Al parecer se trata de un Hashtable en Logback y Log4j, y eso significa que el potencial de un cuello de botella concurrencia sin duda existe. Tenga en cuenta que esto no es una crítica de esos marcos de registro. Por el contrario, el método getLogger no se diseñó/optimizó para ser utilizado de esta manera.

+0

Tenga en cuenta que la sobrecarga de buscar instancias de registrador ya existentes puede incluir especialmente la sincronización. P.ej. logback usa una Hashtable para almacenar en caché los registradores, que es un diccionario sincronizado. La sincronización se producirá en cada llamada a su contenedor de registro, independientemente de si se está registrando un mensaje o no. Yo diría que esto puede matar fácilmente cualquier aplicación de alto tráfico. – lost

+0

@lost - Buen punto. Lo he incorporado en mi respuesta. –

4

Solo tengo que decir que el patrón recomendado es más fácil de leer e implementar. No veo ninguna razón para desviarme de eso. Especialmente sin beneficio.

Sin embargo, mi punto principal es acerca de los guardias mencionados anteriormente. No recomendaría proteger explícitamente sus registros, ya que Log4j ya lo hace internamente y es una duplicación de esfuerzos.

Descargue la fuente para log4j y eche un vistazo a las clases Logger y Category para verlo usted mismo.

9

Para añadir a las razones ya mencionadas, la sugerencia de que su jefe es malo porque:

  • Te obliga a escribir varias veces algo que no tiene nada que ver con la explotación forestal, cada vez que se desea registrar algo: this.getClass()
  • Crea una interfaz no uniforme entre contextos estáticos y no estáticos (porque no hay this en un contexto estático)
  • Los parámetros innecesarios adicionales crean espacio para error, hace posible que las sentencias en la misma clase vayan a diferentes madereros (pensar descuidado c opy pegando)
  • Mientras guarda 74 caracteres de declaración del registrador, agrega 27 caracteres adicionales a cada llamada de registro. Esto significa que si una clase usa el registrador más de 2 veces, está aumentando el código repetitivo en términos de recuento de caracteres.
+1

+1 por copiado descuidado y otros también. – Reddy

6

Al utilizar algo como: MyLoggerWrapper.debug (this.getClass(), "bla") Usted recibirá classnames equivocadas cuando se utiliza marcos AOP o herramientas de código de la inyección. Los nombres de clase no son como el origen, sino un nombre de clase generado. Y otra desventaja de usar el contenedor: para cada declaración de registro, debe incluir el código adicional "MyClass.class".

El 'almacenamiento en caché' de los registradores depende de los marcos utilizados. Pero incluso cuando lo hace, aún debe buscar el registrador deseado para cada declaración de registro que realice. Entonces, teniendo 3 declaraciones en un método, debe buscarlo 3 veces. Utilizándolo como una variable estática, ¡solo debe buscarlo una vez!

Y dicho antes: se pierde la capacidad de usar if (log.isXXXEnabled()) {} para un conjunto de instrucciones.

¿Qué tiene su jefe contra la "forma predeterminada aceptada y recomendada por la comunidad"? Introducir el contenedor no agrega más eficiencia. En su lugar, debe usar el nombre de clase para cada declaración de registro. Después de un tiempo, quiere "mejorar" eso, de modo que agrega otra variable, u otro envoltorio, haciéndolo más difícil para usted.

5

Aquí hay una posibilidad para facilitar el registro en Java 8: defina una interfaz para que lo haga por usted. Por ejemplo:

package logtesting; 

import java.util.Arrays; 

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

public interface Loggable { 
    enum LogLevel { 
     TRACE, DEBUG, INFO, WARN, ERROR 
    } 

    LogLevel TRACE = LogLevel.TRACE; 
    LogLevel DEBUG = LogLevel.DEBUG; 
    LogLevel INFO = LogLevel.INFO; 
    LogLevel WARN = LogLevel.WARN; 
    LogLevel ERROR = LogLevel.ERROR; 

    default void log(Object...args){ 
     log(DEBUG, args); 
    } 

    default void log(final LogLevel level, final Object...args){ 
     Logger logger = LoggerFactory.getLogger(this.getClass()); 
     switch(level){ 
     case ERROR: 
      if (logger.isErrorEnabled()){ 
       logger.error(concat(args)); 
      } 
      break; 
     case WARN: 
      if (logger.isWarnEnabled()){ 
       logger.warn(concat(args)); 
      } 
      break;   
     case INFO: 
      if (logger.isInfoEnabled()){ 
       logger.info(concat(args)); 
      } 
     case TRACE: 
      if (logger.isTraceEnabled()){ 
       logger.trace(concat(args)); 
      } 
      break; 
     default: 
      if (logger.isDebugEnabled()){ 
       logger.debug(concat(args)); 
      } 
      break; 
     } 
    } 

    default String concat(final Object...args){ 
     return Arrays.stream(args).map(o->o.toString()).collect(Collectors.joining()); 
    } 
} 

Entonces todo lo que alguna vez tiene que hacer es asegurarse de que sus clases declaran aplicar Registro, y de ninguno de ellos, se pueden hacer cosas como:

log(INFO, "This is the first part ","of my string ","and this ","is the last"); 

El registro () la función se encarga de concatenar las cadenas, pero solo después de que las pruebas se habiliten. Se inicia la depuración de manera predeterminada, y si desea iniciar sesión para depurar, puede omitir el argumento LogLevel. Este es un ejemplo muy simple. Podría hacer cualquier cantidad de cosas para mejorar esto, como implementar los métodos individuales, es decir, error(), trace(), warn(), etc. También podría simplemente implementar "logger" como una función que devuelve un registrador:

public interface Loggable { 
    default Logger logger(){ 
     return LoggerFactory.getLogger(this.getClass()); 
    } 
} 

Y entonces se vuelve bastante trivial para utilizar su registrador:

logger().debug("This is my message"); 

Usted podría incluso hacer que completamente funcional mediante la generación de métodos de delegado para todos los métodos del registrador, por lo que cada clase de aplicación es una instancia de Logger.

package logtesting; 

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

public interface Loggable extends Logger { 
    default Logger logger(){ 
     return LoggerFactory.getLogger(this.getClass()); 
    } 

    default String getName() { 
     return logger().getName(); 
    } 

    default boolean isTraceEnabled() { 
     return logger().isTraceEnabled(); 
    } 

    default void trace(String msg) { 
     logger().trace(msg); 
    } 

    default void trace(String format, Object arg) { 
     logger().trace(format, arg); 
    } 

    default void trace(String format, Object arg1, Object arg2) { 
     logger().trace(format, arg1, arg2); 
    } 

    default void trace(String format, Object... arguments) { 
     logger().trace(format, arguments); 
    } 

    default void trace(String msg, Throwable t) { 
     logger().trace(msg, t); 
    } 

    default boolean isTraceEnabled(Marker marker) { 
     return logger().isTraceEnabled(marker); 
    } 

    default void trace(Marker marker, String msg) { 
     logger().trace(marker, msg); 
    } 

    default void trace(Marker marker, String format, Object arg) { 
     logger().trace(marker, format, arg); 
    } 

    default void trace(Marker marker, String format, Object arg1, Object arg2) { 
     logger().trace(marker, format, arg1, arg2); 
    } 

    default void trace(Marker marker, String format, Object... argArray) { 
     logger().trace(marker, format, argArray); 
    } 

    default void trace(Marker marker, String msg, Throwable t) { 
     logger().trace(marker, msg, t); 
    } 

    default boolean isDebugEnabled() { 
     return logger().isDebugEnabled(); 
    } 

    default void debug(String msg) { 
     logger().debug(msg); 
    } 

    default void debug(String format, Object arg) { 
     logger().debug(format, arg); 
    } 

    default void debug(String format, Object arg1, Object arg2) { 
     logger().debug(format, arg1, arg2); 
    } 

    default void debug(String format, Object... arguments) { 
     logger().debug(format, arguments); 
    } 

    default void debug(String msg, Throwable t) { 
     logger().debug(msg, t); 
    } 

    default boolean isDebugEnabled(Marker marker) { 
     return logger().isDebugEnabled(marker); 
    } 

    default void debug(Marker marker, String msg) { 
     logger().debug(marker, msg); 
    } 

    default void debug(Marker marker, String format, Object arg) { 
     logger().debug(marker, format, arg); 
    } 

    default void debug(Marker marker, String format, Object arg1, Object arg2) { 
     logger().debug(marker, format, arg1, arg2); 
    } 

    default void debug(Marker marker, String format, Object... arguments) { 
     logger().debug(marker, format, arguments); 
    } 

    default void debug(Marker marker, String msg, Throwable t) { 
     logger().debug(marker, msg, t); 
    } 

    default boolean isInfoEnabled() { 
     return logger().isInfoEnabled(); 
    } 

    default void info(String msg) { 
     logger().info(msg); 
    } 

    default void info(String format, Object arg) { 
     logger().info(format, arg); 
    } 

    default void info(String format, Object arg1, Object arg2) { 
     logger().info(format, arg1, arg2); 
    } 

    default void info(String format, Object... arguments) { 
     logger().info(format, arguments); 
    } 

    default void info(String msg, Throwable t) { 
     logger().info(msg, t); 
    } 

    default boolean isInfoEnabled(Marker marker) { 
     return logger().isInfoEnabled(marker); 
    } 

    default void info(Marker marker, String msg) { 
     logger().info(marker, msg); 
    } 

    default void info(Marker marker, String format, Object arg) { 
     logger().info(marker, format, arg); 
    } 

    default void info(Marker marker, String format, Object arg1, Object arg2) { 
     logger().info(marker, format, arg1, arg2); 
    } 

    default void info(Marker marker, String format, Object... arguments) { 
     logger().info(marker, format, arguments); 
    } 

    default void info(Marker marker, String msg, Throwable t) { 
     logger().info(marker, msg, t); 
    } 

    default boolean isWarnEnabled() { 
     return logger().isWarnEnabled(); 
    } 

    default void warn(String msg) { 
     logger().warn(msg); 
    } 

    default void warn(String format, Object arg) { 
     logger().warn(format, arg); 
    } 

    default void warn(String format, Object... arguments) { 
     logger().warn(format, arguments); 
    } 

    default void warn(String format, Object arg1, Object arg2) { 
     logger().warn(format, arg1, arg2); 
    } 

    default void warn(String msg, Throwable t) { 
     logger().warn(msg, t); 
    } 

    default boolean isWarnEnabled(Marker marker) { 
     return logger().isWarnEnabled(marker); 
    } 

    default void warn(Marker marker, String msg) { 
     logger().warn(marker, msg); 
    } 

    default void warn(Marker marker, String format, Object arg) { 
     logger().warn(marker, format, arg); 
    } 

    default void warn(Marker marker, String format, Object arg1, Object arg2) { 
     logger().warn(marker, format, arg1, arg2); 
    } 

    default void warn(Marker marker, String format, Object... arguments) { 
     logger().warn(marker, format, arguments); 
    } 

    default void warn(Marker marker, String msg, Throwable t) { 
     logger().warn(marker, msg, t); 
    } 

    default boolean isErrorEnabled() { 
     return logger().isErrorEnabled(); 
    } 

    default void error(String msg) { 
     logger().error(msg); 
    } 

    default void error(String format, Object arg) { 
     logger().error(format, arg); 
    } 

    default void error(String format, Object arg1, Object arg2) { 
     logger().error(format, arg1, arg2); 
    } 

    default void error(String format, Object... arguments) { 
     logger().error(format, arguments); 
    } 

    default void error(String msg, Throwable t) { 
     logger().error(msg, t); 
    } 

    default boolean isErrorEnabled(Marker marker) { 
     return logger().isErrorEnabled(marker); 
    } 

    default void error(Marker marker, String msg) { 
     logger().error(marker, msg); 
    } 

    default void error(Marker marker, String format, Object arg) { 
     logger().error(marker, format, arg); 
    } 

    default void error(Marker marker, String format, Object arg1, Object arg2) { 
     logger().error(marker, format, arg1, arg2); 
    } 

    default void error(Marker marker, String format, Object... arguments) { 
     logger().error(marker, format, arguments); 
    } 

    default void error(Marker marker, String msg, Throwable t) { 
     logger().error(marker, msg, t); 
    } 
} 

Por supuesto, como se mencionó antes, esto significa que cada vez que se conecte, tendrá que pasar por el proceso de búsqueda registrador dentro de su LoggerFactory - a menos que anule el método registrador() ... en el cual caso, puede que también lo haga de la manera "recomendada".

+0

Esto no es una mala idea, pero si está utilizando Java 8 con la asombrosa facilidad de Closures, ¿por qué tenemos que tener esas cláusulas de protección? En su código, cada vez que el registro se llama guardia, se invocarán las sentencias y las declaraciones de conmutación. Sin embargo, con cierres (o incluso polimorfismos en general) puede generar una nueva clase de registrador en el inicio de la aplicación que tiene métodos vacíos para niveles de registro bajo el nivel de configuración (a través del archivo de propiedades). –

+1

Usted puede hacer eso. Pero las llamadas a ese método TODAVÍA concatenarán todos los argumentos de cadena si las cláusulas de guardia no están allí ... que es el punto total de usar varargs de objetos en lugar de pasar en un mensaje de cadena edificado. Podrías evitarlo, pero honestamente, llamar a isErrorEnabled() no es notablemente menos eficiente que llamar a un método de error vacío() ... y el punto de la interfaz es que nunca más tendrás que preocuparte por las declaraciones de guardia. Los has escrito una vez y te libras de preocuparte por ellos para siempre. –

+0

@Steve K Me gusta esta solución Tengo algo similar ¿hay un golpe de rendimiento para llamar constantemente a getLogger (this.getClass())? – Selwyn

0

que puede haber perdido en uno de los comentarios anteriores, pero yo no vi mención de que el registrador es estática, la llamada a LoggerFactory se realiza una vez (por creación de instancias de la clase) - por lo que la primera la preocupación por las llamadas múltiples para crear el registrador es simplemente incorrecta.

Los otros comentarios sobre todos los problemas con la adición de clases de ajuste son muy importantes también.

3

Según lo indicado here por el equipo SLF4J puede usar MethodLookup() introducido en JDK 1.7.

final static Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); 

De esta manera se puede hacer referencia a la clase sin la necesidad de utilizar la palabra clave "this".

1

Hay dos razones por las cuales el enfoque de su jefe no logra lo que él piensa.

La razón más pequeña es que la sobrecarga de agregar un registrador estático es despreciable. Después de todo, la configuración del registrador es parte de esta secuencia bastante larga:

  • Ubique la clase, es decir, recorra todos los .jars y directorios. Código Java Bastante grande sobrecarga debido a las llamadas del sistema de archivos. Puede crear objetos auxiliares, p. con File.
  • Cargue el bytecode, es decir, cópielo en una estructura de datos dentro de la JVM. Código nativo.
  • Validar el bytecode. Código nativo.
  • Vincule el bytecode, es decir, itere a través de todos los nombres de clase en el bytecode y reemplácelos con punteros a la clase referida. Código nativo.
  • Ejecutar inicializadores estáticos. Activado desde código nativo, los inicializadores son código Java, por supuesto. El registrador se crea aquí.
  • Después de un tiempo, tal vez JIT-compile la clase. Código nativo. Enorme overhead (en comparación con las otras operaciones de todos modos).

Además, su jefe no ahorra nada.
La primera llamada al LoggerFactor.getLogger creará el registrador y lo colocará en un HashMap de nombre-a-registrador global. Esto sucederá incluso para las llamadas isXxxEnabled, porque para hacer esto necesita construir primero el objeto Logger ...
El objeto Class llevará un puntero adicional para la variable estática. Esto se compensa con la sobrecarga de pasar el parámetro clazz - una instrucción adicional y una referencia de puntero adicional en el bytecode, por lo que ya se pierde al menos un byte en el tamaño de clase.

El código también está pasando por una indirección adicional, LoggerFactory.getLogger(Class) usa Class#getName y delega a LoggerFactory.getLogger(String).

Ahora, si su jefe no busca el rendimiento, pero después de la capacidad de simplemente copiar la declaración estática, puede usar una función que inspecciona la pila de llamadas y recupera el nombre de la clase. La función debe tener la anotación @CallerSensitive, y todavía es algo que debe probarse cada vez que se utiliza una nueva JVM, lo que no es bueno si no se controla la JVM en la que el usuario está ejecutando el código.

El enfoque menos problemático sería tener un IDE que verifique la creación de instancias del registrador. Esto probablemente signifique encontrar o escribir un complemento.

Cuestiones relacionadas