Python GIL Contention: Logging Handlers That Stall Hot Request Paths

Under load, the quietest latency killer in Python services is often logging: every logger.info(...) that touches a FileHandler, WatchedFileHandler, or synchronous HTTP sink holds the GIL while the OS or network waits. Request threads (or asyncio tasks bridged through executors) serialize behind those handlers. You do not fix this by “logging less”—you fix it by making the hot path emit into a lock-free queue and letting a dedicated listener own the I/O.

⚡ TL;DR: Replace hot-path StreamHandler/FileHandler with QueueHandler + QueueListener (or QueueHandler + a single asyncio sink). Measure logging time with py-spy/perf under load; if PyEval_AcquireLock clusters around handlers, you found it. Pair with Python asyncio vs Threading vs Multiprocessing for worker model choices and Lambda Log Buffering: Cut CloudWatch Ingestion Without Losing Correlation for cloud sinks.

Spot GIL stalls caused by handlers

Symptoms look like “CPU is not maxed but p99 jumped.” py-spy dump shows many threads waiting on the GIL; flamegraphs pin frames inside logging/__init__.py or socket.send. Reproduce with a synthetic handler that sleeps under the lock.

# repro/gil_logging_stall.py
import logging, threading, time

class SleepyHandler(logging.Handler):
    def emit(self, record):
        # ❌ Holds work on the logging path (formatting + custom sinks serialize)
        time.sleep(0.005)
        print(self.format(record), flush=True)

log = logging.getLogger("api")
log.setLevel(logging.INFO)
log.addHandler(SleepyHandler())

def handle(_):
    log.info("order=%s", "o-1")  # every request pays the sleep

# 32 threads → near-linear latency blowup vs QueueHandler

QueueHandler + QueueListener pattern

The stdlib pattern moves formatting/I/O off request threads. Emit is cheap: enqueue a LogRecord. One listener thread drains and writes.

# app/logging_setup.py
import logging
import logging.handlers
import queue
from typing import Optional

_listener: Optional[logging.handlers.QueueListener] = None

def configure_async_logging(path: str = "/var/log/api.jsonl") -> None:
    global _listener
    q: queue.Queue = queue.Queue(-1)
    root = logging.getLogger()
    root.setLevel(logging.INFO)
    root.handlers.clear()

    qh = logging.handlers.QueueHandler(q)
    root.addHandler(qh)

    file_h = logging.handlers.WatchedFileHandler(path)
    file_h.setFormatter(logging.Formatter(
        '{"ts":"%(asctime)s","lvl":"%(levelname)s","msg":%(message)s}'
    ))
    # ✅ Listener owns the slow handler; request threads only enqueue
    _listener = logging.handlers.QueueListener(q, file_h, respect_handler_level=True)
    _listener.start()

def shutdown_logging() -> None:
    if _listener:
        _listener.stop()

# ❌ Hot path with FileHandler — every worker contends
logging.basicConfig(
    level=logging.INFO,
    handlers=[logging.FileHandler("/var/log/api.log")],
)

Asyncio services: one writer task

For asyncio FastAPI/aiohttp, prefer a single writer task over a thread listener when the sink is async (HTTP to a collector, aiofiles). Still use QueueHandler so sync libraries do not block the event loop.

# app/async_log_sink.py
import asyncio, logging, logging.handlers, queue

async def run_log_sink(q: queue.Queue, sink) -> None:
    while True:
        try:
            record = q.get_nowait()
        except queue.Empty:
            await asyncio.sleep(0.01)
            continue
        if record is None:
            break
        line = logging.Formatter("%(message)s").format(record)
        await sink.write(line + "\n")

Cross-check sampling and exporter backpressure ideas from Lambda ADOT vs Powertools: Tracing Tradeoffs on Node 20 Runtimes — the same “never block the request on export” rule applies.

What still contends (and how to shrink it)

• Formatting: keep extra= small; avoid json.dumps of huge payloads on the hot path.
• Locks: logging module lock still serializes Logger.handle; QueueHandler minimizes hold time.
• Fork: after os.fork / Gunicorn prefork, restart the listener in each worker (see prefork pitfalls in this batch).
• CloudWatch / Fluent Bit: ship from the listener or sidecar; never PutLogEvents inline per request.

Production rollout

1. Capture a 60s py-spy record under peak; confirm logging frames.
2. Flip one service to QueueListener behind a feature flag; compare p99 and GIL wait.
3. Cap queue size or drop DEBUG under pressure (QueueHandler + filter).
4. On SIGTERM: listener.stop() after draining HTTP, before process exit.
5. Alert on listener lag (queue depth) the same way you alert on outbound queue lag.

Closing checklist

✅ Dos
– ✅ Use QueueHandler + QueueListener (or one async writer) on every hot path
– ✅ Prove wins with py-spy / latency histograms, not vibes
– ✅ Bound queue depth and degrade log level under pressure
– ✅ Restart listeners after fork
– ✅ Keep structured fields tiny on INFO

❌ Don’ts
– ❌ Don’t call network log APIs from request threads
– ❌ Don’t attach FileHandler directly under Gunicorn/uvicorn workers
– ❌ Don’t logger.exception with full request bodies in tight loops
– ❌ Don’t ignore queue growth — that is a silent memory leak
– ❌ Don’t treat “async def” as proof logging is non-blocking

Related reading

• Python asyncio vs Threading vs Multiprocessing
• Lambda Log Buffering: Cut CloudWatch Ingestion Without Losing Correlation
• Lambda ADOT vs Powertools: Tracing Tradeoffs on Node 20 Runtimes
• Python Performance Secrets: 20 Techniques to Make Your Code Faster

Last updated on September 11, 2026