Batched logs example

This example will show you how to optimize you programs execution time by batching the logs emitted by rlh handlers.

Note that in this example, we will use RedisStreamLogHandler but this is valid with any other handlers defined in rlh.

Logger setup

import logging
from rlh import RedisStreamLogHandler

# define the logger
logging.basicConfig()
logger = logging.getLogger()
logger.setLevel(logging.INFO)

Handler with batch size

Logs will be batched if you set the parameter batch_size to a value above 1.

# we will use a batch size of 10
handler = RedisStreamLogHandler(batch_size=10)
# add the handler to the logger
logger.addHandler(handler)

Emit some logs

logger.info("Some log message")
logger.info("Another log message")
logger.error("An error message!")

INFO:root:Some log message
INFO:root:Another log message
ERROR:root:An error message!

Retrieve the logs saved

from redis import Redis

r = Redis(decode_responses=True)
r.xrange("logs", "-", "+")

[]

The list is empty, no logs have been saved! We emitted 3 logs which is less than the specified batch size (10); the logs are currently saved in out handler buffer. Once this buffer length reaches the specified batch size, all the logs are emitted using a pipeline.

We can check that the logs are in the handler buffer:

handler.log_buffer

[{'msg': 'Some log message',
  'levelname': 'INFO',
  'created': 1675347126.6934602},
 {'msg': 'Another log message',
  'levelname': 'INFO',
  'created': 1675347126.695122},
 {'msg': 'An error message!',
  'levelname': 'ERROR',
  'created': 1675347126.6964118}]

Emit more logs

Here we will emit 7 other logs to reach the specified batch size of 10.

for i in range(7):
    logger.info("Another log message %s", i)

INFO:root:Another log message 0
INFO:root:Another log message 1
INFO:root:Another log message 2
INFO:root:Another log message 3
INFO:root:Another log message 4
INFO:root:Another log message 5
INFO:root:Another log message 6

Retrieve logs saved (for real this time)

r.xrange("logs", "-", "+")

[('1675347126898-0',
  {'msg': 'Some log message',
   'levelname': 'INFO',
   'created': '1675347126.6934602'}),
 ('1675347126898-1',
  {'msg': 'Another log message',
   'levelname': 'INFO',
   'created': '1675347126.695122'}),
 ('1675347126898-2',
  {'msg': 'An error message!',
   'levelname': 'ERROR',
   'created': '1675347126.6964118'}),
 ('1675347126898-3',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8935595'}),
 ('1675347126898-4',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8946795'}),
 ('1675347126898-5',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8951957'}),
 ('1675347126898-6',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8959773'}),
 ('1675347126898-7',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8966084'}),
 ('1675347126898-8',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8972368'}),
 ('1675347126898-9',
  {'msg': 'Another log message %s',
   'levelname': 'INFO',
   'created': '1675347126.8977263'})]

Our 10 logs have successfully been saved to Redis; you can notice that all those logs has been saved at the same time.

We can also check that our handler log buffer is now empty:

handler.log_buffer

[]

Remaining logs

If you program end unexpectedly, the remaining batched logs will be emitted, no data will be lost.

# we will use a batch size of 10
handler = RedisStreamLogHandler(batch_size=10, stream_name="remaining_logs")
# add the handler to the logger
logger.addHandler(handler)

logger.info("An info log")

del logger

INFO:root:An info log

r.xrange("remaining_logs", "-", "+")

[]

Execution time comparison

The main advantage of batching logs is to improve execution time. This is relevant only if you application is emitting a large amount of logs within a short period of time.

Here we will emit 1000 logs using RedisStreamLogHandler and compare the execution time with different values of batch size.

import time

# define the logger
logging.basicConfig()
logger = logging.getLogger()
logger.setLevel(logging.INFO)
# removing stdout handler
logger.removeHandler(logging.getLogger().handlers[0])

def emit_n_logs(logger, n_logs):
    """Emits the given amount of log"""
    for i in range(n_logs):
        logger.info("Log n°%s", i)

LOGS_TO_EMIT = 100_000

Execution time without batching

handler = RedisStreamLogHandler(stream_name="no_batch")
# add the handler to the logger
logger.addHandler(handler)

start_time = time.time()
emit_n_logs(logger, LOGS_TO_EMIT)
print(f'{len(r.xrange("no_batch", "-", "+"))} logs saved in {(time.time() - start_time):.3f} seconds')

# remove the handler from logger
logger.removeHandler(handler)

100000 logs saved in 17.078 seconds

Execution time with batch_size=10

handler = RedisStreamLogHandler(batch_size=10, stream_name="batch_10")
# add the handler to the logger
logger.addHandler(handler)

start_time = time.time()
emit_n_logs(logger, LOGS_TO_EMIT)
print(f'{len(r.xrange("no_batch", "-", "+"))} logs saved in {(time.time() - start_time):.3f} seconds')

# remove the handler from logger
logger.removeHandler(handler)

100000 logs saved in 10.752 seconds

Execution time with batch_size=100

handler = RedisStreamLogHandler(batch_size=100, stream_name="batch_100")
# add the handler to the logger
logger.addHandler(handler)

start_time = time.time()
emit_n_logs(logger, LOGS_TO_EMIT)
print(f'{len(r.xrange("no_batch", "-", "+"))} logs saved in {(time.time() - start_time):.3f} seconds')

# remove the handler from logger
logger.removeHandler(handler)

100000 logs saved in 9.959 seconds

Execution time with batch_size=1_000

handler = RedisStreamLogHandler(batch_size=1_000, stream_name="batch_1000")
# add the handler to the logger
logger.addHandler(handler)

start_time = time.time()
emit_n_logs(logger, LOGS_TO_EMIT)
print(f'{len(r.xrange("no_batch", "-", "+"))} logs saved in {(time.time() - start_time):.3f} seconds')

# remove the handler from logger
logger.removeHandler(handler)

100000 logs saved in 10.023 seconds

Execution time with batch_size=10_000

handler = RedisStreamLogHandler(batch_size=10_000, stream_name="batch_10000")
# add the handler to the logger
logger.addHandler(handler)

start_time = time.time()
emit_n_logs(logger, LOGS_TO_EMIT)
print(f'{len(r.xrange("no_batch", "-", "+"))} logs saved in {(time.time() - start_time):.3f} seconds')

# remove the handler from logger
logger.removeHandler(handler)

100000 logs saved in 9.771 seconds

If batch_size is well chosen, it can greatly reduce the execution time of you program.