如何剥离 Python 日志记录调用而不将它们注释掉？

Posted 2023-02-18

【中文标题】如何剥离 Python 日志记录调用而不将它们注释掉？

【英文标题】：How can I strip Python logging calls without commenting them out?

【发布时间】：2010-10-06 01:58:51

【问题描述】：

今天我正在考虑我大约一年前写的一个 Python 项目，我在其中非常广泛地使用了logging。我记得由于开销（hotshot 表示这是我最大的瓶颈之一），我不得不在类似内部循环的场景（90% 的代码）中注释掉许多日志记录调用。

我现在想知道是否有一些规范的方法可以以编程方式去除 Python 应用程序中的日志记录调用，而无需一直注释和取消注释。我认为您可以使用检查/重新编译或字节码操作来执行类似的操作并仅针对导致瓶颈的代码对象。这样，您可以添加一个操纵器作为编译后步骤并使用集中配置文件，如下所示：

[Leave ERROR and above]
my_module.SomeClass.method_with_lots_of_warn_calls

[Leave WARN and above]
my_module.SomeOtherClass.method_with_lots_of_info_calls

[Leave INFO and above]
my_module.SomeWeirdClass.method_with_lots_of_debug_calls

当然，您可能希望谨慎使用它，并且可能以每个函数为粒度 - 仅适用于已显示 logging 成为瓶颈的代码对象。有人知道这样的事吗？

注意：由于动态类型和后期绑定，有几件事会使以高性能方式执行此操作变得更加困难。例如，对名为debug 的方法的任何调用可能必须用if not isinstance(log, Logger) 包装。无论如何，我假设所有的小细节都可以通过君子协议或一些运行时检查来克服。 :-)

【问题讨论】：

您使用相同的根级记录器吗？即，logging.getLogger()？如果是这样，你需要先解决这个问题。如果没有，请在这些模块中提供一些 getLogger 调用。

@S.Lott：我在每个模块的基础上使用 LOG = logging.getLogger(name)，然后调用 LOG.debug(msg) 等。不过，我真的不明白它的相关性。

【参考方案1】：

使用logging.disable怎么样？

我还发现，如果创建日志消息的成本很高，我必须使用 logging.isEnabledFor。

【讨论】：

logging.isEnabledFor 可能会起作用，因为我认为是对 Logger 方法的调用看起来很合适。我喜欢这是一个潜在的解决方案，尽管做条件创建很烦人。我将尝试挖掘旧代码库，看看是否可行。

事实证明，这正是Logger.debug 的实现方式：svn.python.org/view/python/tags/r26/Lib/logging/…

其实，进一步看logging 代码，这可能是我需要的优化。 getEffectiveLevel 遍历记录器层次结构，而disable 将消除该遍历。谢谢！

问题是，记录器的参数仍在评估中，这往往是记录器成本的来源。例如：logging.info("My msg %s", some_expensive_call()) 即使使用了 logging.disable，some_expensive_call 仍然会被调用和评估。

您仍然必须使用 if 语句。我认为 python 会在运行时通过检查不同记录器的日志级别并删除每个记录器的日志级别以下的语句来在内部处理这个问题。可惜没有。

【参考方案2】：

使用pypreprocessor

也可以在 PYPI (Python Package Index) 上找到并使用 pip 获取。

这是一个基本的用法示例：

from pypreprocessor import pypreprocessor

pypreprocessor.parse()

#define nologging

#ifdef nologging
...logging code you'd usually comment out manually...
#endif

基本上，预处理器会按照您之前手动执行的方式输出代码。它只是根据您的定义有条件地即时执行。

您还可以通过在导入和 parse() 语句。

字节码输出 (.pyc) 文件将包含优化后的输出。

旁注：pypreprocessor 与 python2x 和 python3k 兼容。

免责声明：我是 pypreprocessor 的作者。

【讨论】：

我通常不是预处理器指令的忠实粉丝。在这种方法上，我已经走到了虚无的边缘，当时没有 Unix 做事的方式与任何其他 Unix 完全相同，而且它并不漂亮。 OTOH，该功能可以作为外部模块添加，这真是太棒了。在某些情况下……它可能正是您所需要的。

@Jonathan 我也不是，但在某些特殊情况下，它可能会大大减少维护。我最初创建它是为了能够在同一个文件中运行 py2x 和 py3x 代码（多个版本的并行开发），但是词法分析器在预处理器甚至可以运行之前使代码无效。对于这样的情况，它应该可以完美地工作。它本质上只是打开自己，读取代码，删除不必要的代码分支，然后运行修改后的输出。非常 hacky，但它的效果出奇的好，尤其是因为您也可以将后处理的代码保存为文件。

将我的代码包装在#define nologging 块中会给我NameError: global name 'logging' is not defined

【参考方案3】：

我也见过以这种方式使用断言。

assert logging.warn('disable me with the -O option') is None

（我猜警告总是不返回任何内容。如果没有，你会得到一个 AssertionError

但实际上，这样做只是一种有趣的方式：

if __debug__: logging.warn('disable me with the -O option')

当您使用 -O 选项运行包含该行的脚本时，该行将从优化的 .pyo 代码中删除。相反，如果您有自己的变量，如下所示，您将有一个始终执行的条件（无论变量是什么值），尽管条件应该比函数调用更快地执行：

my_debug = True
...
if my_debug: logging.warn('disable me by setting my_debug = False')

所以如果我对 debug 的理解是正确的，这似乎是摆脱不必要的日志调用的好方法。不利的一面是它还会禁用您的所有断言，因此如果您需要断言，这是一个问题。

【讨论】：

是的，在每次调用前都加上断言实在是太丑陋了。将if my_debug 放在所有内容前面同样不受欢迎和不雅——我希望有一些东西可以自动剥离/修改它们。 :-( 此外，始终使用 is None 与 None 进行显式比较。:-)

【参考方案4】：

作为一个不完美的捷径，在特定模块中使用MiniMock 之类的东西来模拟logging 怎么样？

例如，如果my_module.py 是：

import logging
class C(object):
    def __init__(self, *args, **kw):
        logging.info("Instantiating")

您可以将 my_module 的使用替换为：

from minimock import Mock
import my_module
my_module.logging = Mock('logging')
c = my_module.C()

您只需在初始导入模块之前执行一次。

通过模拟特定方法或让logging.getLogger 返回一个模拟对象，其中一些方法无效，而另一些则委托给真正的logging 模块，从而获得特定于关卡的行为非常简单。

在实践中，您可能希望将 MiniMock 替换为更简单、更快的东西；至少不会将使用情况打印到标准输出的东西！当然，这并不能解决模块 A 从模块 B 导入 logging 的问题（因此 A 也导入了 B 的日志粒度）...

这永远不会像根本不运行日志语句那样快，但应该比一直深入到日志模块的深处才发现根本不应该记录这条记录要快得多。

【讨论】：

这实际上听起来比字节码操作要理智得多，因为字节码操作技术不一定会跨 VM 移植。我看到的唯一问题是您只能通过堆栈跟踪检查找出 哪个 方法调用了您，如果我没记错的话，这也会很慢。

啊，好吧..所以我认为模拟对象会非常愚蠢，不关心（或不知道）它们是从哪里调用的。您将只有每个模块的配置粒度，而不是每个功能。恐怕选择将模拟对象注入哪个模块是您唯一的灵活性。

【参考方案5】：

你可以试试这样的：

# Create something that accepts anything
class Fake(object):
    def __getattr__(self, key):
        return self
    def __call__(self, *args, **kwargs):
        return True

# Replace the logging module
import sys
sys.modules["logging"] = Fake()

它本质上用Fake 的实例替换（或最初填充）日志模块的空间，它只接受任何东西。在尝试在任何地方使用日志记录模块之前，您必须运行上述代码（只需一次！）。 这是一个测试：

import logging

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(levelname)-8s %(message)s',
                    datefmt='%a, %d %b %Y %H:%M:%S',
                    filename='/temp/myapp.log',
                    filemode='w')
logging.debug('A debug message')
logging.info('Some information')
logging.warning('A shot across the bows')

按照上述情况，没有任何记录，正如预期的那样。

【讨论】：

所以您无法按模块或按级别选择性地打开或关闭日志记录？

【参考方案6】：

我会使用一些花哨的日志装饰器，或者一堆：

def doLogging(logTreshold):
    def logFunction(aFunc):
        def innerFunc(*args, **kwargs):
            if LOGLEVEL >= logTreshold:
                print ">>Called %s at %s"%(aFunc.__name__, time.strftime("%H:%M:%S"))
                print ">>Parameters: ", args, kwargs if kwargs else "" 
            try:
                return aFunc(*args, **kwargs)
            finally:
                print ">>%s took %s"%(aFunc.__name__, time.strftime("%H:%M:%S"))
        return innerFunc
    return logFunction

您只需要在每个模块中声明 LOGLEVEL 常量（或仅在全局范围内并在所有模块中导入它），然后您就可以像这样使用它：

@doLogging(2.5)
def myPreciousFunction(one, two, three=4):
    print "I'm doing some fancy computations :-)"
    return

如果 LOGLEVEL 不小于 2.5，您将得到如下输出：

>>Called myPreciousFunction at 18:49:13
>>Parameters:  (1, 2) 
I'm doing some fancy computations :-)
>>myPreciousFunction took 18:49:13

如您所见，需要做一些工作才能更好地处理 kwargs，因此如果存在默认值，则会打印它们，但这是另一个问题。

您可能应该使用一些 logger 模块而不是原始的 print 语句，但我想专注于装饰器的想法并避免使代码过长。

无论如何 - 使用这样的装饰器，您可以获得功能级别的日志记录、任意多个日志级别、易于应用到新功能以及禁用日志记录，您只需设置 LOGLEVEL。如果您愿意，您可以为每个函数定义不同的输出流/文件。你可以将 doLogging 写成：

 def doLogging(logThreshold, outStream=sys.stdout):
      .....
      print >>outStream, ">>Called %s at %s" etc.

并利用基于每个功能定义的日志文件。

【讨论】：

我使用 logging 模块从 inside 方法记录内容 - 您的方法只能记录外部可见的内容（args、kwargs、返回值和执行时间)。

您曾写过有关在每个函数粒度上使用日志记录的文章，而您的伪代码示例也暗示了类似的内容。我的方法可以扩展——你可以在你的函数中添加额外的关键字参数。而那个额外的参数将是一个记录器或虚拟对象，由装饰器提供:-)

不是一个理想的解决方案，我同意，但是 - 装饰器是高度可扩展的，不是吗？

我认为您缺少的部分是日志调用是从 inside 函数进行的，以及 对 Logger.debug 本身的调用 导致减速。您确实需要从方法中删除这些调用。

您可以使用装饰器来检查函数的代码并重写/重新编译它，但这基本上相当于字节码后处理器。现在我想它实际上可能比后处理更好，所以 +1 指向一个好的方向！

【参考方案7】：

这是我的项目中的一个问题，因为日志记录最终会非常一致地出现在分析器报告中。

我之前在 PyFlakes (http://github.com/kevinw/pyflakes) 的一个分支中使用过 _ast 模块......而且绝对可以按照您在问题中的建议进行操作——在调用日志记录方法之前检查和注入警卫（并承认您必须进行一些运行时类型检查）。一个简单的例子见http://pyside.blogspot.com/2008/03/ast-compilation-from-python.html。

编辑：我刚刚在我的planetpython.org 提要上注意到MetaPython——示例用例是在导入时删除日志语句。

也许最好的解决方案是让某人将日志记录重新实现为 C 模块，但我不会是第一个抓住这样一个......机会的人：p

【参考方案8】：

:-) 我们曾经称它为预处理器，尽管 C 的预处理器具有其中的一些功能，但“山中之王”是 IBM 大型机 PL/I 的预处理器。它在预处理器中提供了广泛的语言支持（完整赋值、条件、循环等），并且可以仅使用 PL/I PP 编写“编写程序的程序”。

我编写了许多应用程序，其中包含成熟的复杂程序和数据跟踪（当时我们没有合适的后端进程调试器）用于开发和测试，然后在使用适当的“运行时标志”只是简单地剥离了所有跟踪代码，而没有任何性能影响。

我认为装饰器的想法很好。您可以编写一个装饰器来包装需要记录的函数。然后，对于运行时分发，装饰器变成了“无操作”，消除了调试语句。

乔恩·R

【参考方案9】：

我目前正在做一个项目，该项目使用大量日志记录来测试使用 Pandas 库的数据分析 API 的逻辑和执行时间。

我发现这个字符串有类似的问题 - 例如即使 logging.basicConfig 级别设置为 level=logging.WARNING，logging.debug 语句的开销是多少

我已经编写了以下脚本来在部署之前注释掉或取消注释调试日志：

import os
import fileinput

comment = True

# exclude files or directories matching string
fil_dir_exclude = ["__","_archive",".pyc"]

if comment :
    ## Variables to comment
    source_str = 'logging.debug'
    replace_str = '#logging.debug'
else :
    ## Variables to uncomment
    source_str = '#logging.debug'
    replace_str = 'logging.debug'

# walk through directories
for root, dirs, files in os.walk('root/directory') :
    # where files exist
    if files:
        # for each file
        for file_single in files :
            # build full file name
            file_name = os.path.join(root,file_single)
            # exclude files with matching string
            if not any(exclude_str in file_name for exclude_str in fil_dir_exclude) :
                # replace string in line
                for line in fileinput.input(file_name, inplace=True):
                    print "%s" % (line.replace(source_str, replace_str)),

这是一个文件递归，它根据条件列表排除文件，并根据此处找到的答案执行就地替换：Search and replace a line in a file in Python

【参考方案10】：

我喜欢 'if __debug_' 解决方案，只是把它放在每次调用之前有点分散注意力和丑陋。我遇到了同样的问题，并通过编写一个脚本来克服它，该脚本自动解析您的源文件并用 pass 语句替换日志语句（并注释掉日志语句的副本）。它还可以撤消此转换。

当我将新代码部署到生产环境中时，我会使用它，因为在生产环境中有很多我不需要的日志语句并且它们正在影响性能。

你可以在这里找到脚本：http://dound.com/2010/02/python-logging-performance/