java - example - ¿Por qué no se recomienda llamar a LoggerFactory.getLogger(...) cada vez?
slf4j example (12)
He leído un montón de publicaciones y documentos (en este sitio y en otros) señalando que el patrón recomendado para el registro de SFL4J es:
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 usemos un contenedor para interceptar las llamadas de registro y evitar el código de la placa de la caldera 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 usándolo así:
public class MyClass {
public void myMethod() {
//do some stuff
MyLoggerWrapper.debug(this.getClass(), "blah blah blah");
}
}
Supongo que crear instancias de un registrador cada vez que registramos es un poco caro, 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 para señalar posibles problemas con este enfoque?
Aquí hay un problema obvio con este enfoque: los mensajes String se construirán en cada llamada a debug() , no hay una forma obvia de usar una cláusula guard con su envoltorio.
La expresión estándar con log4j / commons-logging / slf4j es usar una cláusula de guardia como:
if (log.isDebugEnabled()) log.debug("blah blah blah");
Con el propósito de que si el nivel de DEBUG no está habilitado para el registrador, el compilador puede evitar la concatenación de cadenas más largas que pueda enviarlo:
if (log.isDebugEnabled()) log.debug("the result of method foo is " + bar
+ ", and the length is " + blah.length());
Consulte "¿Cuál es la forma más rápida de (no) iniciar sesión?" en las preguntas frecuentes SLF4J o log4j .
Recomendaría contra el "envoltorio" que sugiere tu 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 hace mucho más larga: compare lo anterior con
MyLoggerWrapper.debug(Foo.class, "some message");
Este es el tipo de "envolver" y ofuscación trivial y sin importancia que no tiene otra finalidad que agregar capas de direccionamiento indirecto y feo-fying de su código. Creo que su jefe puede encontrar problemas más importantes sobre los que obsesionarse.
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 tienes que hacer es asegurarte de que tus clases declaren implementar Logged , y de cualquiera de ellas, puedes hacer cosas como:
log(INFO, "This is the first part ","of my string ","and this ","is the last");
La función log () se encarga de concatenar sus 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 luego se vuelve bastante trivial usar tu registrador:
logger().debug("This is my message");
Incluso podría hacerlo completamente funcional generando métodos de delegado para todos los métodos de Logger, de modo que cada clase de implementación sea 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ó anteriormente, esto significa que cada vez que inicie sesión, tendrá que pasar por el proceso de búsqueda del registrador dentro de su LoggerFactory, a menos que anule el método logger () ... en cuyo caso también podría hacerlo la forma "recomendada".
Como se establece here por el equipo SLF4J, puede usar MethodLookup () introducido en JDK 1.7.
final static Logger logger = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
De esta forma puede consultar la clase sin la necesidad de utilizar la palabra clave "this".
Cuando se usa algo como: MyLoggerWrapper.debug (this.getClass (), "blah") Obtendrá nombres de clases incorrectos cuando use frameworks AOP o herramientas de inyección de código. 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: usted pierde la capacidad de usar if (log.isXXXEnabled ()) {} para un conjunto de declaraciones.
¿Qué tiene su jefe contra la "forma aceptada y recomendada por defecto de 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 que lo haga más difícil para usted.
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 insignificante. Después de todo, la configuración del registrador es parte de esta secuencia bastante larga:
- Ubique la clase, es decir, recorra todos los .jar y directorios. Código Java Bastante grande sobrecarga debido a las llamadas del sistema de archivos. Puede crear objetos auxiliares, por ejemplo, con
File. - Cargue el bytecode, es decir, cópielo en una estructura de datos dentro de la JVM. Código nativo.
- Valide el bytecode. Código nativo.
- Enlace 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 sobrecarga (en comparación con las otras operaciones de todos modos).
Además, tu jefe no ahorra nada.
La primera llamada a 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 adicional del tamaño del puntero en el bytecode, por lo que ya se pierde al menos un byte en el tamaño de la clase.
El código también está pasando por una indirección adicional, LoggerFactory.getLogger(Class) utiliza la Class#getName y delega en 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 usa 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 instanciación del registrador. Esto probablemente signifique encontrar o escribir un complemento.
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 1 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 problemas mencionados por otras respuestas también son importantes:
- Su aplicación ya no puede usar
logger.isDebugEnabled()para minimizar los gastos generales cuando la depuración está deshabilitada. - La clase
MyLoggerWrapperoculta 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
MyLoggerWrapperprobablemente 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.
Finalmente, esto es simplemente "no de la manera en que se hace".
1 - Aparentemente es una Hashtable en Logback y Log4j, y eso significa que el potencial para un cuello de botella de concurrencia definitivamente existe. Tenga en cuenta que esto no es una crítica de esos marcos de registro. Por el contrario, el método getLogger no fue diseñado / optimizado para ser utilizado de esta manera.
Los objetos del registrador seguramente se vuelven a utilizar, por lo que no habrá instancias adicionales de ninguna manera. El problema más grande que veo es que su información de número de archivo / línea será inútil, ya que el registrador siempre registrará fielmente que cada mensaje fue emitido desde la clase LoggerWrapper , línea 12 :-(
OTOH SLF4J ya es una fachada de contenedor para ocultar el marco de trabajo de registro específico utilizado, lo que le permite cambiar libremente entre diferentes implementaciones de registro. Por lo tanto, no veo absolutamente ningún motivo para esconder eso detrás de otra envoltura.
No. No es otra cosa que arruina 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.
Para agregar a las razones ya mencionadas, la sugerencia de su jefe es mala porque:
- Te obliga a escribir repetidamente algo que no tiene nada que ver con el registro, cada vez que quieras registrar algo:
this.getClass() - Crea una interfaz no uniforme entre contextos estáticos y no estáticos (porque no existe
thisen un contexto estático) - Los parámetros innecesarios adicionales crean espacio para el error, posibilita que las declaraciones en la misma clase vayan a diferentes registradores (piense en copiar de forma descuidada)
- 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.
Puede que no lo haya visto en uno de los comentarios anteriores, pero no vi una mención de que el registrador es estático , la llamada a LoggerFactory se hace UNA VEZ (por instanciación de la clase), por lo que la preocupación inicial sobre las llamadas múltiples para crear el registrador está simplemente equivocado.
Los otros comentarios sobre todos los problemas con la adición de clases de ajuste son muy importantes también.
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 de log4j y eche un vistazo a las clases Logger y Category para verlo usted mismo.
Versión 2015 de la respuesta: por favor libere su mente con lombok @ slf4j .