Logs y métricas

Lo que no se define no se puede medir. Lo que no se mide, no se puede mejorar. Lo que no se mejora, se degrada siempre

— William Thomson Kelvin

En este post voy a hablar sobre un caso real que hace poco hemos tenido en Tymit relativo a laimportancia de poder medir la ejecución de tu software.

Sin entrar en muchos detalles, porque seguramente muchos os sentiréis identificados, en Tymit tenemos un procesode negocio crítico donde intervienen varios componentes (llámalos microservicios, aplicaciones, librerías) y que devez en cuando tardaba algo más de lo esperado generando los problemas típicos (timeouts, reintentos, consumo de recursos,etc).

Por supuesto contamos con toda la infraestructura necesaria para no perder ni una sola línea de logs, capacidad paraasumir los reintentos y demás mecanismos para mantener el nivel de servicio …​ actual. Pero ¿qué pasaría ante unincremento de la demanda de dicha funcionalidad? Obviamente era un flujo de trabajo que había que revisar y mejorar.

Como ya he comentado, todo el flujo se encuentra debidamente traceado y todos los logs son capturados y enviados aun ELK (ElasticSearch y Kibana) para su supervisión de tal forma que es relativamente fácil sabercuando comienza un flujo y los pasos principales por donde va pasando.

Sin embargo el problema principal es que esta línea de seguimiento de logs suele estar pensaba para que el desarrollador puedaidentificar los pasos por los que ha transcurrido una transacción (casi siempre comparándolo con el código fuente eidentificando las decisiones tomadas en función de la traza que veamos). Obviamente cuanto mayor información se dispongaen el log más fácil será identificar las decisiones tomadas por el código

WARNING

No, tracear un método con "entra aquí" o "paso 1", no te va a sacar del apuro

Como es obvio, en esta situación un desarrollador puede ir realizando un seguimiento de cómo se comporta su código enproducción pero el sistema sigue adoleciendo de algunas deficiencias:

• Negocio y QA, en el mejor de los casos tienen una curva de aprendizaje elevada en el aprendizaje de lo que están viendo

• Se asume que como cada línea de log incluye su marca de tiempo seremos capaces de extraer información sobre el tiempoempleado en resolver cada paso, lo cual puede ser cierto en el mejor de los casos, pero la realidad es que o se disponede un sistema robusto o el análisis se hace con un coste de análisis elevado

Traceo básico

Una primera aproximación puede ser la de tracear la entrada a cada método de interés así como todos los posibles retornosque se puedan producir dentro del método.

int calculoCostoso( int param1, String param2){
    log.info "calculoCostoso:enter "+new Date().time
    if( !param2 ){
        log.info "calculoCostoso:exit "+new Date().time
        return -1
    }
    int ret = param1*10
    log.info "calculoCostoso:exit "+new Date().time
    return ret
}

Obviamente esta es una solución rápida pero costosa y propensa a error. Así mismo delegamos en el sistema de explotaciónde los logs el cálculo de cuánto ha tardado la función en ejecutarse.

Una posible mejora podría ser tomar tiempos de entrada y de salida y tracear la diferencia:

int calculoCostoso( int param1, String param2){
    Date start = new Date()
    if( !param2 ){
        log.info "calculoCostoso:duration "+ (new Date().time-start.time)
        return -1
    }
    int ret = param1*10
    log.info "calculoCostoso:duration "+ (new Date().time-start.time)
    return ret
}

A parte de lo tedioso y propenso a error del sistema, existen otras situaciones que no estaríamos contemplando comopor ejemplo si se producen excepciones dentro del método, por lo que podríamos reescribir cada método de interéscon algo parecido a:

int calculoCostoso( int param1, String param2){
    Date start = new Date()
    try{
        if( !param2 ){
            return -1
        }
        int ret = param1*10
        return ret
    }finally{
        log.info "calculoCostoso:duration "+ (new Date().time-start.time)
    }
}

Slf4j y MDC

Log4j y Logback ofrecen, además del traceo básico, la posibilidad de utilizar MDC (Mapped Diagnostic Context)

Con MDC puedes "enriquecer" el sistema de traceo con otros tipos de datos además de la línea a tracear. Un caso típicopuede ser por ejemplo añadir un id de contexto al inicio del flujo de tal forma que todos los logs que se generenen ese thread compartirán este correlation Id facilitando su agrupación.

Estos campos pueden ser utilizados en sistemas tipo ELK (ElasticSearch-Logstack-Kibana) para mejorar los sistemasde búsqueda y filtrado así como generar gráficas en tiempo real, etc.

Nosotros podemos aprovechar esta funcionalidad para añadir una pequeña carga de información en el log. Así por ejemplopodríamos mejorar nuestro método:

int calculoCostoso( int param1, String param2){
    Date start = new Date()
    log.info "calculoCostoso:enter"
    try{
        if( !param2 ){
            return -1
        }
        int ret = param1*10
        return ret
    }finally{
        MDC.put("payload", JsonOutput.toJson([className: 'BussinesService',
                                            methodName: 'calculoCostoso',
                                            duration: new Date().time-start.time]))
        log.info "calculoCostoso:exit"
        MDC.remove("payload")
    }
}

MeterMethod

MeterMethod es una clase muy simple destinada a medir el tiempo desde su creación hasta que se invoca el método toString. Además permite incluir en la cadena a generar una lista de key-value (tags) así como el incluir/remover en el MDCun payload con la información de interés

NOTE

payload puede llamarse como quieras, es un campo que se añade en el contexto de la traza y simplemente debes buscar un nombre que no "pise" a alguno ya existente. La idea es que estos campos del MDC lleguen al ELK y puedan ser indexados para su búsqueda y explotación

class MeterMethod {

    long start
    Map<String, String> tags = [:]
    String methodName
    String className

    MeterMethod(String className, String methodName) {
        this.className = className
        this.methodName = methodName
        start = Calendar.instance.timeInMillis
    }

    long getDuration() {
        Calendar.instance.timeInMillis - start
    }

    void addTag(String key, Object value) {
        tags[key] = '' + value
    }

    @Override
    String toString() {
        String args = tags.size() ? tags.collect { "$it.key=$it.value" }.join(';') : ''
        "$className.$methodName: duration=$duration ms;$args"
    }

    void addPayload() {
        MDC.put("payload", JsonOutput.toJson([className: className, methodName: methodName, duration: duration]))
    }

    void removePayload() {
        MDC.remove("payload")
    }
}

Un posible ejemplo de su uso sería:

int calculoCostoso( int param1, String param2){
    def meterMethod = new MeterMethdo(this.class.Name, 'calculoCostoso')
    meterMethod.addTag('param1', param1)

    try{
        if( !param2 ){
            return -1
        }
        int ret = param1*10
        return ret
    }finally{
        meterMethod.addPayload()
        log.info meterMethod.toString()
        meterMethod.removePayload()
    }
}

Anotación TymitTrace

NOTE

El stack tecnológico que utilizamos en Tymit es Groovy&Grails pero no debería ser difícil adaptar esta anotación a Java.

Con todas estas ideas y teniendo en cuenta que ya disponemos de toda una infraestructura capaz de realizar la ingesta(me gusta esta palabra) de los logs y su visualización en Kibana, nos planteamos usar esta estrategia para poder disponerde unas métricas básicas pero evitando el tener que tocar en la medida de lo posible un código que estaba funcionando,por lo que hemos creado una anotación a nivel de método que aplique la técnica descrita anteriormente.

TymitTrace

@Local(
        value = TymitTraceTransformation,
        applyTo = Local.TO.METHOD)
@interface TymitTrace {
    /**
     * A list of variables to trace, i.e 'a,b,c'
     * @return
     */
    String value()
}

Para usar dicha anotación, simplemente anotaremos los métodos de interés:

@TymitTrace
int calculoCostoso( int param1, String param2){
    if( !param2 ){
        return -1
    }
    int ret = param1*10
    return ret
}

Dando vida a la anotación

Una anotación en sí no es nada más que una declaración de buenas intenciones entre el que la usa y el que la implementa.Es un contrato, de ahí que sea una interface, que hay que implementar. Dicha implementación en el mundo de lasanotaciones corresponderá a un código que inyecta código en otro código (qué vértigo!!)

Cuando el compilador encuentre una anotación, bien sea de clase, de propiedad o de método buscará la clase que se encuentraindicada en dicha anotación y le cederá el turno en el proceso de generar código.

Así pues deberemos crear la clase TymitTraceTransformation que implementará dicha anotación tal como indicamos enla anotación de la anotación (doble vértigo!!)

NOTE

Gracias a la librería de @marioggar (grooviter/asteroid) implementar una anotación para Groovy es bastante fácil.

NOTE

Gracias a @ilopmar por publicar un Gist (https://gist.github.com/ilopmar/6037796) que me sirvió para inspirarme en esta anotación

@CompileStatic
@Phase(CompilePhase.SEMANTIC_ANALYSIS)
class TymitTraceTransformation extends AbstractLocalTransformation<TymitTrace, MethodNode> {
    static private List pool = ['a'..'z', 'A'..'Z', '0'..'9', '_'].flatten()

    @Override
    void doVisit(final AnnotationNode annotation, final MethodNode methodNode) {
        def oldCode = methodNode.code
        def className = methodNode.declaringClass.name
        def methodName = methodNode.name
        def parameters = Utils.NODE.get(annotation, 'value', String) ?: ''
        def rand = new Random(System.currentTimeMillis())
        def randomVariableName = '_' + (0..10).collect { pool[rand.nextInt(pool.size())] }.join('')
        methodNode.code = blockS(
            declareMeterMethod(randomVariableName, className, methodName),
            declareClosure(randomVariableName, parameters.split(','), meter),
            tryCatchSBuilder()
                    .tryStmt(
                            oldCode
                    )
                    .finallyStmt(
                            callFinish(randomVariableName)
                    )
                    .build()
        )
    }

    // generamos código similar a
    // def _a12BadF123 = new MeterMethod('BusinessService', 'calculoCostoso')
    Statement declareMeterMethod(String randomVariableName, String className, String methodName) {
        stmt(varDeclarationX(randomVariableName, MeterMethod,
                newX(MeterMethod, constX(className), constX(methodName))
        ))
    }

    // generamos código similar a
    /**
      def _a12BadF123Closure = {
        _a12BadF123.addTag('param1', param1)
        _a12BadF123.addPayload()
        log.info _a12BadF123.toString()
        _a12BadF123.removePayload()
    }*/
    Statement declareClosure(String randomVariableName, String[] parameters, Boolean meter) {
        String closureStr = parameters.findAll { it }.collect { String p ->
            "${randomVariableName}.addTag('$p',$p)"
        }.join('\n')

        closureStr += """
                ${randomVariableName}.addPayload()
                log.info ${randomVariableName}.toString()
                ${randomVariableName}.removePayload()
        """

        Statement closure = blockSFromString(closureStr)
        stmt(varDeclarationX(randomVariableName + 'Closure', Closure, closureX(closure)))
    }

    // generamos código similar a :
    // _a12BadF123Closure.call()
    Statement callFinish(String randomVariableName) {
        stmt(callX(varX("${randomVariableName}Closure"), 'call'))
    }

}

Básicamente lo que hacemos es EN TIEMPO DE COMPILACIÓN recubrir nuestro método con un try-finally:

Cambiamos el código del nodo por uno nuevo:

• declaramos una variable randomVariableName del tipo MeterMethod

• creamos una Closure para ser llamada al final

• recubrimos el método original con un try-finally donde en el try llamaremos al método original y en el finallyinvocaremos nuestra closure. Al ser un try-finally el retorno de la función seguirá siendo el que realice el métodooriginal

La Closure que ejecutamos en el finally es la encargada de recabar, una vez ejecutado el método original, la informaciónnecesaria para el traceo (duration, tags y preparar el MDC). Como puede verse la hemos implementado con un "simple"String de tal forma que es más fácil de entender.

Resultado final

Con todo ello podremos proceder a anotar nuestros métodos con TymitTrace . Si lo hacemos en el ejemplo inicialde esta manera:

@TymitTrace('param1,param2') (1)
int calculoCostoso( int param1, String param2){
    if( !param2 ){
        return -1
    }
    int ret = param1*10
    return ret
}

| 1 | Simplemente añadimos esta línea sin tocar el código original |

A grandes rasgos el código final que se genera EN TIEMPO DE COMPILACIÓN podría ser parecido a:

int calculoCostoso( int param1, String param2){
    MeterMethod _123aAdfkl123lf = new MeterMethod( 'BusinessService', 'calculoCostoso')
    try{
        if( !param2 ){
            return -1
        }
        int ret = param1*10
        return ret
    }finally{
        _123aAdfkl123lf.addTag('param1', param1)
        _123aAdfkl123lf.addTag('param2', param2)
        _123aAdfkl123lf.addPayload()
        log.info _123aAdfkl123lf.toString()
        _123aAdfkl123lf.removePayload()
    }
}

Log

Si simplemente usas la consola (o un volcado a fichero de la misma) esta anotación te proporciona información "en bruto"valiosa pues tendrás trazas como:

2020-06-18 12:00:00 INFO:BusinessService BusinessService.calculoCostoso: duration=123 ms;1,hola

Pero si conectas el sistema de logs con un ELK podrás acceder a los campos del payload y obtener la información deforma más cómoda y práctica, pudiendo realizar por ejemplo gráficas en tiempo real.

En nuestro caso, por ejemplo, queríamos poder medir las mejoras que íbamos realizando al proceso pesado y que no quedaraen un parece que ahora bien así que una vez implementando este sistema de traceo-métrica pudimos ir abordando lasmejoras al proceso y obtener este gráfico donde se veía el antes y el después del despliegue de una de las versiones