惯用的 Python 日志记录：格式字符串 + args 列表与内联字符串格式 - 首选哪个？

Posted 2023-02-22

【中文标题】惯用的 Python 日志记录：格式字符串 + args 列表与内联字符串格式 - 首选哪个？

【英文标题】：Idiomatic Python logging: format string + args list vs. inline string formatting - which is preferred?

【发布时间】：2012-08-10 22:48:42

【问题描述】：

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

我见过（并写过）使用内联字符串格式的日志记录代码：

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

但我认为使用它更好（在性能方面，并且更惯用）：

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

因为第二种形式在调用日志记录函数之前避免了字符串格式化操作。如果当前日志级别会过滤掉日志消息，则无需格式化，从而减少计算时间和内存分配。

我是在正确的轨道上，还是我错过了什么？

【问题讨论】：

我认为你在正确的轨道上。

您有关于在不同时间进行字符串格式化的时间的参考吗？我本来希望两者都发生在拨打warn 之前。不争论你在说什么，只是想了解更多。

嗯，在第一种形式中，我们在调用logging.warn之前进行字符串格式化（和元组创建）之前 - 在第二种情况，我们只是将一个 args 列表传递给 logging.warn（这仅仅是创建元组？） - 所以我们避免在调用时进行字符串格式化操作。正如我在问题中提到的，我假设如果当前的日志记录级别会过滤掉日志消息，则不会进行格式化，再次避免字符串格式化操作。我的猜想是这应该节省处理时间和内存分配。

@Inactivist Ah .. 好的，感谢您提供更多信息。我想您可以根据我提供的时间以及您已有的信息得出自己的结论。我想另一种方法可能是计算实际调用的时间并查看它们的比较？

Lazy logger message string evaluation 的可能重复项

【参考方案1】：

如果这有帮助，这里是对两个格式选项的快速计时测试：

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

似乎给第二种方法带来了优势。

【讨论】：

接下来调用% with log 函数呢？

所以，我可以从你的回答中学到最重要的一课：时间是我的朋友！ :D

@Inactivist 我发现它很有用.. 经常验证（或反驳）我关于什么是快速的和什么不是的假设:)

是否有类似的简单方法来确定两种变体之间的内存消耗差异？

@Inactivist 我也想知道这一点，不幸的是，没有找到了。如果有的话，我很想知道。

【参考方案2】：

恕我直言，对于很可能会显示的消息，例如发送给 error 或 warn 的消息，这并没有太大的区别。

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

更新

我刚刚检查了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

在实践中，这可以带来相当高的性能提升。

【讨论】：

如果日志记录处于性能关键循环中，这可能会有所不同。

这就是我根据观察所期望的。感谢您进行源潜水！

Python 3.6 f 字符串格式显示相同的时间损失：python -m timeit -n 1000000 -s "import logging" -s "logger = logging.getLogger('foo')" -s "logger.setLevel(logging.ERROR)" -s "x=list(range(0,100))" "logger.warn(f'x')" 每个循环产生 10 微秒，与经典样式字符串格式相同。将格式化参数直接传递给日志语句会产生 2.12 微秒。

【参考方案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 pointed out，整体性能差异取决于格式化字符串所需的时间（这可能很重要，具体取决于在传递给日志记录函数的参数上调用__str__ 的成本。）