Logging optimizations galaxy brain

logging-optimizations.md

Logging optimizations

We will examine the byte code to get a sense of how much work the interpreter is doing.

Setup

>>> import logging
>>> logger = logging.getLogger()
>>> from dis import dis

Case 1: Check if it's enabled every time.

>>> def f():
...     if logger.isEnabledFor(10):
...             logger.debug("message")
... 
>>> dis(f)
  2           0 LOAD_GLOBAL              0 (logger)
              2 LOAD_METHOD              1 (isEnabledFor)
              4 LOAD_CONST               1 (10)
              6 CALL_METHOD              1
              8 POP_JUMP_IF_FALSE       20

  3          10 LOAD_GLOBAL              0 (logger)
             12 LOAD_METHOD              2 (debug)
             14 LOAD_CONST               2 ('message')
             16 CALL_METHOD              1
             18 POP_TOP
        >>   20 LOAD_CONST               0 (None)
             22 RETURN_VALUE

Case 2: Stash if it's enabled in a global variable, as suggested by the documentation.

>>> enabled = logger.isEnabledFor(10)
>>> def f():
...     if enabled:
...             logger.debug("message")
... 
>>> dis(f)
  2           0 LOAD_GLOBAL              0 (enabled)
              2 POP_JUMP_IF_FALSE       14

  3           4 LOAD_GLOBAL              1 (logger)
              6 LOAD_METHOD              2 (debug)
              8 LOAD_CONST               1 ('message')
             10 CALL_METHOD              1
             12 POP_TOP
        >>   14 LOAD_CONST               0 (None)
             16 RETURN_VALUE

This saved us several LOAD_* calls and a METHOD_CALL compared to Case 1.

Case 3: Use compile-time __debug__ flag

>>> def f():
...     if __debug__:
...             logger.debug("message")
... 
>>> dis(f)
  3           0 LOAD_GLOBAL              0 (logger)
              2 LOAD_METHOD              1 (debug)
              4 LOAD_CONST               1 ('message')
              6 CALL_METHOD              1
              8 POP_TOP
             10 LOAD_CONST               0 (None)
             12 RETURN_VALUE

When __debug__ is true, the compiler includes the block under if __debug__: in the byte code. The value of __debug__ is set at compile time and does not need to be loaded and evaluated runtime. Thus, we saved:

  2           0 LOAD_GLOBAL              0 (enabled)
              2 POP_JUMP_IF_FALSE       14

compared to Case 2 even when the block runs. If we run Python with optimizations python -O, the block under if __debug__: is omitted entirely from the byte code. When run in that mode, all that f does is load None and return it:

>>> def f():
...     if __debug__:
...             logger.debug("message")
... 
>>> dis(f)
  3           0 LOAD_CONST               0 (None)
              2 RETURN_VALUE