TopolearnUnderstanding the pipeline lets you debug odd behaviour and keep logging cheap in hot paths.
What log.info("x %s", v) does, step by step:
isEnabledFor(INFO)is checked first. The result is cached per logger and reset whenever levels change, so disabled calls are very cheap.logging.disable(level)globally short-circuits at this point.findCaller()walks the stack for file, line and function name, one of the most expensive steps.- A
LogRecordis created (through the factory you can replace withsetLogRecordFactory), with time, thread, process and the unformattedmsgandargs. - Logger filters run, then
callHandlerswalks the logger and its ancestors whilepropagateis True. - Each handler checks its level, runs its filters, then acquires its lock (handlers are thread-safe) and calls
emit, which callsformat. The message is merged with args at this point, ingetMessage().
Performance tips from the docs: set logging.logThreads, logging.logProcesses, logging.logMultiprocessing and logging.logAsyncioTasks (3.12) to False to skip collecting those fields. Avoid extra dicts built on every call in hot loops. Formatters cache the exception text in record.exc_text.
Errors inside emit go to handler.handleError, which prints a traceback but doesn't raise, unless logging.raiseExceptions is False, when they are silently ignored.
Example
import logging, sys, timeit
log = logging.getLogger("hot")
log.addHandler(logging.StreamHandler(sys.stdout))
log.setLevel(logging.WARNING)
n = 100_000
off = timeit.timeit(lambda: log.debug("x=%s", 1), number=n)
logging.disable(logging.CRITICAL) # global kill switch
dis = timeit.timeit(lambda: log.warning("x=%s", 1), number=n)
logging.disable(logging.NOTSET)
print(f"filtered debug: {off / n * 1e9:.0f} ns/call")
print(f"disabled: {dis / n * 1e9:.0f} ns/call")
old = logging.getLogRecordFactory()
def factory(*a, **kw):
rec = old(*a, **kw); rec.service = "api"; return rec
logging.setLogRecordFactory(factory)
log.handlers[0].setFormatter(logging.Formatter("%(service)s %(message)s"))
log.warning("custom field") # api custom fieldRemember
- Level checks happen first and are cached, so filtered calls are cheap
- findCaller and record creation dominate the cost of emitted calls
- Handlers are lock-protected; errors in emit are reported, not raised
Watch out for
- Wrapping log calls in try/except: logging already swallows handler errors via handleError.