懒惰的日志消息字符串评估

Question

我在我的Python应用程序中使用标准的Python日志模块：

import logging
logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("log")
while True:
  logger.debug('Stupid log message " + ' '.join([str(i) for i in range(20)]) )
  # Do something

问题是，尽管调试级别没有启用，但那个烦人的日志信息在每次循环迭代时都会被计算，这严重影响了性能。

有没有什么解决办法呢？

在C++中，我们有一个叫做log4cxx的包，它提供了像这样的宏：
LOG4CXX_DEBUG(logger, message)
这个宏可以有效地计算为

if (log4cxx::debugEnabled(logger)) {
    log4cxx.log(logger,log4cxx::LOG4CXX_DEBUG, message)
}

但是在Python中（据我所知）没有宏，有没有什么高效的方式来进行日志记录呢？

Answer 1

import logging
import time

logging.basicConfig(level=logging.INFO)
logger = logging.getLogger("log")

class Lazy(object):
    def __init__(self,func):
        self.func=func
    def __str__(self):
        return self.func()

logger.debug(Lazy(lambda: time.sleep(20)))

logger.info(Lazy(lambda: "Stupid log message " + ' '.join([str(i) for i in range(20)])))
# INFO:log:Stupid log message 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19

如果你运行这个脚本，你会发现第一个 logger.debug 命令并没有花费20秒来执行。这说明当日志级别低于设定的级别时，传入的参数并不会被计算。

Answer 2

当然，下面这个方法没有宏那么高效：

if logger.isEnabledFor(logging.DEBUG):
    logger.debug(
        'Stupid log message ' + ' '.join([str(i) for i in range(20)])
    )

但是它简单，采用懒惰求值的方式，并且比被接受的答案快4倍：

class lazyjoin:
    def __init__(self, s, items):
        self.s = s
        self.items = items

    def __str__(self):
        return self.s.join(self.items)

logger.debug(
    'Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20)))
)

可以查看这个链接了解我的设置。

Answer 3

这个日志模块已经部分支持你想要的功能。你可以这样做：

log.debug("Some message: a=%s b=%s", a, b)

... 而不是这样：

log.debug("Some message: a=%s b=%s" % (a, b))

这个日志模块很聪明，只有在消息真的被记录的时候，它才会生成完整的日志信息。

为了把这个功能应用到你的具体需求上，你可以创建一个叫做lazyjoin的类。

class lazyjoin:
    def __init__(self, s, items):
        self.s = s
        self.items = items
    def __str__(self):
        return self.s.join(self.items)

你可以这样使用它（注意使用了生成器表达式，这样可以让它更懒惰）：

logger.info('Stupid log message %s', lazyjoin(' ', (str(i) for i in range(20))))

这里有一个演示，展示了这个功能是如何工作的。

>>> import logging
>>> logging.basicConfig(level=logging.INFO)
>>> logger = logging.getLogger("log")
>>> class DoNotStr:
...     def __str__(self):
...         raise AssertionError("the code should not have called this")
... 
>>> logger.info('Message %s', DoNotStr())
Traceback (most recent call last):
...
AssertionError: the code should not have called this
>>> logger.debug('Message %s', DoNotStr())
>>>

在演示中，logger.info()的调用触发了断言错误，而logger.debug()没有到达那一步。