Python Async Logging

You've built a high-performance Python application using asyncio, but you've noticed a bottleneck. The culprit? Your logging. This is a common issue as logging seems to be a a trivial operation, but it can be a significant performance killer.

By default, Python's logging module uses blocking handlers, which means your application pauses every time it writes a log message. Before we delve right in, it's important to say that in most cases, synchronous logging is perfectly fine. It's simple, reliable, and the default behavior. It works well for applications that aren't I/O-bound or where logging operations are infrequent.

But if you're building a high-performance I/O-bound application, you'll want to consider asynchronous logging. This article will walk you through why traditional logging can slow down your code and how to implement a simple yet effective asynchronous logging solution using Python's standard library.

Why do we even need to care about async logging? Here's a simple example:

import logging
import time

logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(message)s')

def process_data(item):
    """Simulates a blocking data processing task."""
    logging.info(f"Starting to process item: {item}")
    time.sleep(0.1)  # Simulates work
    logging.info(f"Finished processing item: {item}")

if __name__ == "__main__":
    data_items = range(5)
    for item in data_items:
        process_data(item)

    logging.info("All data processed.")

When you move into a high-concurrency environment, this approach falls apart.

With the Async logging approach, instead of writing directly to a file or a remote service, log messages are placed in a queue and processed in a separate thread. This allows your primary application code to continue executing without waiting for the I/O to complete.

Imagine a web server handling thousands of concurrent requests. If each request logs synchronously, the application spends valuable time waiting for log files to be written. This increases latency and drastically reduces the number of requests it can handle per second. Asynchronous logging solves this by offloading the logging work to a background thread.

The good part, is you don't need a third-party library to achieve this. Python's standard library provides the logging.handlers.QueueHandler and logging.handlers.QueueListener for this exact purpose.

First, create a Queue, then use QueueHandler. By using these, you'll create a thread-safe queue that will hold the log messages, then, the your main application logger will use the QueueHandler to put log records into the queue. This is a non-blocking operation, so your app remains fast.

Lastly, use QueueListener. It runs in a separate thread. It reads messages from the queue and passes them to a "worker handler" (e.g., a FileHandler) that performs the actual, slow I/O operation.

Here's another code example:

import logging
from logging.handlers import QueueHandler, QueueListener
from queue import Queue
import threading
import time
import asyncio

# 1. Setup a queue for logging
log_queue = Queue(-1)

# 2. Setup the worker handler that will actually write the logs
worker_handler = logging.FileHandler("async_app.log")
worker_handler.setFormatter(logging.Formatter('%(asctime)s - %(message)s'))

# 3. Setup the listener in a separate thread
listener = QueueListener(log_queue, worker_handler)
listener.start()

# 4. Setup the main application logger to use the QueueHandler
async_handler = QueueHandler(log_queue)
logger = logging.getLogger('my_async_app')
logger.addHandler(async_handler)
logger.setLevel(logging.INFO)

async def handle_request(request_id):
    """Simulates a fast, asynchronous request handler."""
    logger.info(f"Async: Starting request {request_id}")
    await asyncio.sleep(0.01)  # Simulate non-blocking work
    logger.info(f"Async: Finishing request {request_id}")

async def main():
    """Simulates a high-concurrency environment."""
    tasks = [handle_request(i) for i in range(10)]
    await asyncio.gather(*tasks)

if __name__ == "__main__":
    start_time = time.time()
    asyncio.run(main())
    end_time = time.time()
    logger.info(f"Total time elapsed: {end_time - start_time:.4f} seconds")

    # It's important to stop the listener gracefully
    listener.stop()

Happy logging!