Python中惯用的日志记录方式：格式字符串+参数列表 vs 内联字符串格式化 - 哪种更受欢迎？

Question

使用格式字符串+参数列表调用日志函数是否有优助于内联格式化？

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

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

不过我认为更好（从性能和习惯用法方面考虑）的方法是使用：

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

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

我是否理解正确？还是有什么我忽略了的地方？

- Inactivist

---

我认为你走在了正确的道路上。 - mgilson

你有关于不同时间进行字符串格式化的参考资料吗？我本来以为在调用warn之前两者都会发生。并不是质疑你所说的，只是想更加好奇地了解一下。 - Levon

@Inactivist 啊..好的，谢谢你提供的额外信息。我想你可以根据我提供的时间和你已经拥有的信息得出自己的结论。或许另一种方法是计时实际调用并比较它们的时间？ - Levon

可能是Lazy logger message string evaluation的重复问题。 - Steven Rumbalski

@Levon：这很重要。请看我的回答，或者是user1202136的回答。 - Inactivist

Answer 1

在我看来，对于那些很可能被展示的消息，比如给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)

可以观察到在调用log和检查日志级别之间，msg和args没有被改变。

更新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

实际上，这可以显著提高性能。

- user1202136

---

另一个可能会产生影响的时间是如果记录在性能关键循环中。 - Steven Rumbalski

根据我的观察，这正是我所预期的。感谢您进行源代码挖掘！ - Inactivist

Python 3.6 的 f-string 格式化显示了相同的时间惩罚：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微秒。 - Dustin Wyatt

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

看起来第二种方法更有优势。

- Levon

---

@Vladimir 我不确定，因此我对我的答案进行了限定。 - Levon

你的意思是第二种方法更占优势吗？同时请注意，这里你正在计时元组创建与元组创建和字符串插值。但我不确定这实际上如何转化为logging模块在参数等方面的操作。 - mgilson

@mgilson 是的，第二个 -- 谢谢！关于另一个问题，我在 OP 的帖子下面的评论中询问了时序问题 - 我本来期望在发送到 warn() 之前两个字符串都已经被格式化了 - 难道不是这样吗？那么在这种情况下，对 warn() 的调用和随后的操作将是恒定的。 - Levon

@levon：Python 有内存分析工具，但可惜我找到的没有一个像 timeit 那样易于使用！ - Inactivist

我不确定我第二条评论的真正含义。如果字符串被记录，那么字符串插值必须在某个时刻发生。如果您实际上没有记录消息（则可以跳过插值），则从方法2中获益。我想知道使用*args的函数调用的时间差异取决于是否实际给出任何*args。 - mgilson

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__的成本）。

- Inactivist