惯用Python日志:格式字符串+ args列表与内联字符串格式 - 这是首选？

Question

使用格式字符串+ args列表与格式内联调用日志记录函数是否有利？

我已经看过(并写过)使用内联字符串格式的日志代码:

logging.warn("%s %s %s" % (arg1, arg2, arg3))

但我认为使用它更好(性能方面,更具惯用性):

logging.warn("%s %s %s", arg1, arg2, arg3)

因为第二种形式在调用日志记录功能之前避免了字符串格式化操作.如果当前日志记录级别将过滤掉日志消息,则不需要格式化,从而减少了计算时间和内存分配.

我在这里是正确的轨道,还是我错过了什么？

Answer 1

恕我直言,对于很可能被显示的消息,例如给出的消息,error或者warn它没有太大的区别.

对于不太可能显示的消息,我肯定会选择第二个版本,主要是出于性能原因.我经常将大对象作为参数给出info,这实现了一种代价高昂的__str__方法.显然,发送这种预先格式化的内容info将是一种性能浪费.

UPDATE

我刚检查了logging模块的源代码,确实在检查日志级别后完成了格式化.例如:

class Logger(Filterer):
    # snip
    def debug(self, msg, *args, **kwargs):
        # snip
        if self.isenabledfor(debug):
            self._log(debug, msg, args, **kwargs)

人们可以观察到msg并且args在调用log和检查日志级别之间不受影响.

更新2

由Levon开发,让我为具有昂贵__str__方法的对象添加一些测试:

$ python -m timeit -n 1000000 -s "import logging" -s "logger = logging.getLogger('foo')" -s "logger.setLevel(logging.ERROR)" "logger.warn('%s', range(0,100))"
1000000 loops, best of 3: 1.52 usec per loop
$ python -m timeit -n 1000000 -s "import logging" -s "logger = logging.getLogger('foo')" -s "logger.setLevel(logging.ERROR)" "logger.warn('%s' % range(0,100))"
1000000 loops, best of 3: 10.4 usec per loop

在实践中,这可以提供相当高的性能提升.

Answer 2

如果这有用,这里只是两个格式化选项的快速计时测试:

In [61]: arg1='hello'
In [62]: arg2='this'
In [63]: arg3='is a test'

In [70]: timeit -n 10000000 "%s %s %s" % (arg1, arg2, arg3)
10000000 loops, best of 3: 284 ns per loop

In [71]: timeit -n 10000000  "%s %s %s", arg1, arg2, arg3
10000000 loops, best of 3: 119 ns per loop

似乎给了第二种方法的优势.

Answer 3

如果当前日志记录级别过滤日志消息（如我所料），则避免内联字符串格式确实可以节省一些时间——但不会太多：

In [1]: import logging

In [2]: logger = logging.getLogger('foo')

In [3]: logger.setLevel(logging.ERROR)

In [4]: %timeit -n 1000000 logger.warn('%s %s %s' % ('a', 'b', 'c'))
1000000 loops, best of 3: 1.09 us per loop

In [12]: %timeit -n 1000000 logger.warn('%s %s %s', 'a', 'b', 'c')
1000000 loops, best of 3: 946 ns per loop

因此，正如user1202136 指出的那样，整体性能差异取决于格式化字符串所需的时间（这可能很重要，具体取决于调用__str__传递给日志函数的参数的成本。）