Escritura de logs asincronica

[UrielPaluch]

Objetivo

Utilizando py-spy encontré que la escritura de logs es sumamente costosa, pero es algo necesario. Podría intentar implementar una escritura de logs asincrónica. La idea es que se escriban los logs cuando haya algún hueco en cola de ejecución.

Hay dos formas de hacerlo, una es con asyncio y la otra con threads. Creo que asyncio es el enfoque correcto, porque la idea sería mandar a escribir y continuar con la ejecución (como si fuera un db).

Planificación

Tengo una lista donde voy appendeando los logs y luego que escirba cuando encuentra un hueco. Hay que pensar bien como se integra con el módulo de logging de toolbox.

• Probar escribir un log con la librería Toolbox.
• Probar escribir un log con el handler BufferingHandler, que escribe el log en batches.
• Armar una clase que tome dos parámetros: name: str y testing: bool, y escriba los logs en batch.
• Crear la carpeta "log" en la inicialización.
• Implementar una función que haga el flush.
• Testear la velocidad, comparado con el método "normal" (TimedRotatingFileHandler). #8

• A tener en cuenta:
  • Sacar (levelname)s del yaml
  • A los logs les tengo que agregar un timestamp para poder tener el momento real de cuando se ejecuta.

resultados

Tiempo de Logging

Testeando el tiempo que demora en loggear, para el MemoryHandler comparado con el FileHandler, obtengo estos resultados loggeando 400.000 logs, con una capacidad de 10000 para el MemoryHandler:

Batch Logger: log time 5345ms, flush time 2ms
Normal Logger: 6729ms
Batch Logger is 1.26 times faster than the normal logger.

Simulación con .log file real

Ahora, testero lo mismo que antes, pero loggeando mensajes reales de un log file de ejemplo.
El log file tiene 460.000 líneas. El código corre 10 veces la simulación de loggear todas las líneas, inicializando los loggers a cada vez.
La capacity la settee a 20.000, que sería el valor por defecto.

Normal Logger: 14493ms
Batch Logger: 7624ms
Batch Logger is 1.90 times faster than the normal logger.

Next Steps

• Cambiar el método ".log()" por ".info()", ".debug()" y el resto.
• Correr un test más exhaustivo del tiempo
• Buscar e implementar forma más eficiente de concatenar strings. Update: Parece que sumar strings es más eficiente.
• Investigar cantidad razonable de Logs para que funcione bien (capacidad máxima). Haciendo un cálculo rápido, viendo que nos gustaría consumir como máximo 2 megas en memoria, se seteó la capacidad por defecto en 20.000 logs.
• Las funciones de log tienen que quedar asi, ejemplo:

def info(self, message: str, *args) -> None:
        """
        Loggea el mensaje en memoria con nivel info.

        Parameters
        ----------
        message : str
            Mensaje a loggear.
        """
        formatted_message = self.format_log_message(message.format(*args))
        self.logger.info(formatted_message)
        print(formatted_message)

Porque si no no se puede logguear lazy, logger.info("El entorno de ejecucion es %s", entorno.name), y no imprime los logs.

• Llevarlo a producción. Cuando lo llevemos a producción hay que cambiar en el requirements.txt como se instala Toolbox porque yo (Uri) lo tuve que cambiar porque lo llevamos a prod antes de que corresponda. (este comentario es para hacerte que me acuerde de contarte bien que es lo que hicimos mal, mas allá de que te lo escribí por wp). Llevarlo a prod implica hacerlo en Tito y en CaucionColocadora.

[Eitan-Sprejer]

Copio el código que usé para testear el tiempo que tarda cada logger

from src.toolbox.logging_module.logging_module import NormalLogger, BatchLogger
import timeit
import numpy as np

def run_simulation(n_simulations: int=10, capacity: int=1000):
    """
    Corre la simulación de logging.
    """

    normal_logging_time_list = []
    batch_logging_time_list = []
    for _ in range(n_simulations):
        normal_logger = NormalLogger('normal', testing=True)
        batch_logger = BatchLogger('batch', capacity=capacity, testing=True)
        normal_logging_time_list.append(simulate_normal_logging(normal_logger))
        batch_logging_time_list.append(simulate_batch_logging(batch_logger))
    normal_logging_time = np.mean(normal_logging_time_list)
    batch_logging_time = np.mean(batch_logging_time_list)

    print(f'Normal Logger: {normal_logging_time*1000:.0f}ms')
    print(f'Batch Logger: {batch_logging_time*1000:.0f}ms')
    print(f'Batch Logger is {normal_logging_time/batch_logging_time:.2f} times faster than the normal logger.')

def simulate_normal_logging(logger: NormalLogger):
    """
    Simula el logging de mensajes.
    """
    messages = load_test_log()

    tic = timeit.default_timer()

    for message in messages:
        logger.info(message)
    toc = timeit.default_timer()

    return toc - tic

def simulate_batch_logging(logger: BatchLogger):
    """
    Simula el logging de mensajes.
    """
    messages = load_test_log()

    tic = timeit.default_timer()

    for message in messages:
        logger.info(message)
    logger.flush()
    toc = timeit.default_timer()

    return toc - tic

def load_test_log():
    """
    Carga el log de prueba.
    """
    with open('./logs/testing.log', 'r') as file:
        lines = file.readlines()
    log_messages = [line.split(' :: ')[-1][:-1] for line in lines]

    return log_messages

if __name__ == '__main__':
    # Simulating logging
    run_simulation(capacity=20000)