Python GIL Contention: Logging Handlers That Stall Hot Request Paths

# 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

# 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")],
)

# 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")