Todo en esta vida tiene un coste, incluso el logging (II)

En la anterior entrada había conectado la idea de que a veces el logging es innecesario y que Java nos ofrece una funcionalidad que nos viene de perlas para evitarlo.

Luego de sesudas reflexiones, he dedicido llamar a esta técnica con el rimbombante nombre de "assert logging."

Ehm, ¿el qué? Vale, sí, el nombre es una mierda. Se aceptan sugerencias.

Pero vamos a lo interesante, implementación y pruebas…

Implementación

La idea está clara: añadir una instrucción assert a cada línea de log que sólo se vaya a escribir en desarrollo. Si para producción se establece el log a nivel WARN, por ejemplo, todos los niveles inferiores deberían llevar un assert.

Para hacer esto mantenible, creamos un wrapper en torno al logger de turno. Sí, todos odiamos hacer wrappers de wrappers de wrappers, pero no hay otra opción. Esto, además, nos permite salvar una pequeña dificultad a la hora de encajar el assert: la expresión a asertar debe evaluar a verdadero o falso y, por lo general, los métodos de log no devuelven nada.

Con estas premisas, y basándome en slf4j, una posible implementación sería:

public class Log {
  private final Logger logger;

  public Log(Class<?> cls) {
    logger = LoggerFactory.getLogger(cls);
  }

  public void debug(String msg) {
    assert _debug(msg);
  }
  private boolean _debug(String msg) {
    logger.debug(msg);
    return true;
  }
}

Esta clase se usaría para reemplazar a los Logger normales del framework de logging, y habría que dedicarle un ratillo para completar el API hasta que se asemeje al que usa dicho framework. Una vez completada, el código original de la aplicación no tendría por qué cambiar ni en una línea.

Código de test

Una vez construida la técnica, vamos con el código de prueba. En realidad la idea es muy simple, usamos un bucle un tanto largo para hacer un cálculo estúpido y añadimos una línea de log. Para que el compilador no haga de las suyas, añadimos un factor de entropía en forma de número aleatorio:

for (int i = 0; i < Integer.MAX_VALUE; i++) {
  rnd += r.nextInt() % 2;
  logger.debug("rnd");
}

Sé que es un caso muy extremo, se trataba de ejercitar exactamente eso. Pero vaya, que levante la mano el que nunca haya puesto una línea de log dentro de un bucle.

He preparado un pequeño proyecto en GitHub con todo el código de esta entrada para que puedas probarlo en tu máquina y cuentes al mundo tus resultados. Basta con descargarlo comprimido en ZIP, extraerlo a una carpeta, navegar hasta el directorio raiz del proyecto con una consola y ejecutar “gradlew run” (lo cual descargará unos cuantos megas de internet).

Numeritos

En mi máquina, un AMD E1-1200, he obtenido los siguientes resultados:

Sin logSLF4JAssert logging
Milisegundos (media de 4 ejecuciones)611297396061859

Una diferencia de 10 segundos en una tarea de 60… Te imagino con una mueca similar a la que puse yo en su momento.

Y para que puedas comparar, la potencia del AMD E1 es similar a la que tiene la microinstancia de AWS que se usa para servir este blog.

Autor

Héctor

Viendo los bytes pasar desde mi ventana