懒惰记录器消息字符串评估

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, messasage)
有效地评估为

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

但是由于Python(AFAIK)中没有宏,是否有一种有效的记录方法？

Answer 1

日志记录模块已经部分支持您要执行的操作.做这个:

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()没有达到那么远.

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

请参阅benchmark-src以了解我的设置.

Answer 3

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 4

正如Shane指出的那样,使用

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

......而不是这个:

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

如果实际记录了消息,则仅通过执行字符串格式化来节省一些时间.

但是,这并不能完全解决问题,因为您可能需要预先处理值以格式化为字符串,例如:

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

在这种情况下,obj.get_a()和obj.get_b()将被计算,即使在没有日志记录也会.

解决方法是使用lambda函数,但这需要一些额外的机制:

class lazy_log_debug(object):
    def __init__(self, func):
        self.func = func
        logging.debug("%s", self)
    def __str__(self):
        return self.func()

...然后您可以使用以下内容进行登录:

lazy_log_debug(lambda: "Some message: a=%s b=%s" % (foo.get_a(), foo.get_b()))

在这种情况下,只有在log.debug决定执行格式化时才会调用lambda函数,因此调用该__str__方法.

请注意:该解决方案的开销可能会超出收益:-)但至少在理论上,它可以完成完全懒惰的日志记录.