Python日志记录性能比较和选项

28

我正在研究Python中的高性能日志记录,但到目前为止,我对Python标准日志记录模块的性能感到失望 - 但似乎没有其他选择。以下是一段代码,用于性能测试4种不同的日志记录方式:

import logging
import timeit
import time
import datetime
from logutils.queue import QueueListener, QueueHandler
import Queue
import threading

tmpq = Queue.Queue()

def std_manual_threading():
    start = datetime.datetime.now()
    logger = logging.getLogger()
    hdlr = logging.FileHandler('std_manual.out', 'w')
    logger.addHandler(hdlr)
    logger.setLevel(logging.DEBUG)
    def logger_thread(f):
        while True:
            item = tmpq.get(0.1)
            if item == None:
                break
            logging.info(item)
    f = open('manual.out', 'w')
    lt = threading.Thread(target=logger_thread, args=(f,))
    lt.start()
    for i in range(100000):
        tmpq.put("msg:%d" % i)
    tmpq.put(None)
    lt.join()
    print datetime.datetime.now() - start

def nonstd_manual_threading():
    start = datetime.datetime.now()
    def logger_thread(f):
        while True:
            item = tmpq.get(0.1)
            if item == None:
                break
            f.write(item+"\n")
    f = open('manual.out', 'w')
    lt = threading.Thread(target=logger_thread, args=(f,))
    lt.start()
    for i in range(100000):
        tmpq.put("msg:%d" % i)
    tmpq.put(None)
    lt.join()
    print datetime.datetime.now() - start


def std_logging_queue_handler():
    start = datetime.datetime.now()
    q = Queue.Queue(-1)

    logger = logging.getLogger()
    hdlr = logging.FileHandler('qtest.out', 'w')
    ql = QueueListener(q, hdlr)


    # Create log and set handler to queue handle
    root = logging.getLogger()
    root.setLevel(logging.DEBUG) # Log level = DEBUG
    qh = QueueHandler(q)
    root.addHandler(qh)

    ql.start()

    for i in range(100000):
        logging.info("msg:%d" % i)
    ql.stop()
    print datetime.datetime.now() - start

def std_logging_single_thread():
    start = datetime.datetime.now()
    logger = logging.getLogger()
    hdlr = logging.FileHandler('test.out', 'w')
    logger.addHandler(hdlr)
    logger.setLevel(logging.DEBUG)
    for i in range(100000):
        logging.info("msg:%d" % i)
    print datetime.datetime.now() - start

if __name__ == "__main__":
    """
    Conclusion: std logging about 3 times slower so for 100K lines simple file write is ~1 sec while std
    logging ~3. If threads are introduced some overhead causes to go to ~4 and if QueueListener and events
    are used with enhancement for thread sleeping that goes to ~5 (probably because log records are being
    inserted into queue).
    """
    print "Testing"
    #std_logging_single_thread() # 3.4
    std_logging_queue_handler() # 7, 6, 7 (5 seconds with sleep optimization)
    #nonstd_manual_threading() # 1.08
    #std_manual_threading() # 4.3

非标准手动线程选项效果最佳,因为没有日志模块的开销,但显然您会错过许多功能,如格式化程序、过滤器和良好的界面。 单线程中的std_logging是次佳选择,但仍比非标准手动线程慢约3倍。 std_manual_threading选项将消息转储到线程安全队列中,并在单独的线程中使用标准日志记录模块。这大约比第二个选项高25%,可能是由于上下文切换成本造成的。 最后,使用“logutils”的QueueHandler选项是最昂贵的。我调整了logutils / queue.py的_monitor方法的代码,在处理500个消息后睡眠10毫秒,只要队列中的消息少于100K,就可以将运行时间从7秒降至5秒(可能是由于避免上下文切换成本造成的)。
我的问题是,为什么日志记录模块存在如此多的性能开销?是否有任何替代方案?作为一个性能敏感的应用程序,使用日志记录模块甚至有意义吗? P.S.:我已经对不同的情况进行了分析,似乎LogRecord的创建很耗费资源。

冒着成为"那个人"的风险--您的进程预计会生成多少输出行,需要编写多少输出行才能花费1秒额外的计算时间?日志记录将占用您总计算时间的百分比是多少?看起来您必须记录大量的数据,才能在运行时间上真正注意到实际差异--至少对于长时间运行的进程(这很重要)... - mgilson
2
有道理,但我正在努力做出关于如何获得最佳日志模块性能的明智决策。我考虑的应用程序每秒接收数千个实时事件,我的日志记录器表现得越好,我就越能感到“ok”记录这些事件,因为它们在重新创建问题发生的条件方面非常有用。 - Sid
关于您对我的答案的评论 - 感谢提供数据点。套接字接收器是否在单独的机器上?此外,您可以尝试用更简洁的版本覆盖“SocketHandler.makePickle”(如果您不需要发送所有内容 - 对于发送字典而言,pickle 可能过于复杂)。通过步骤2、3、4减少了多少时间? - Vinay Sajip
@VinaySajip 套接字是本地的(同一台机器)。第二步可以节省约10-12%,并涉及logging._srcfile = None,llogging.logThreads = 0和llogging.logProcesses = 0。第三步结果波动较大。从StreamHandler的emit中删除acquire和release有时会将延迟降低近20%,但在其他情况下仅降低2%。这可能是基于操作系统如何调度线程而随机发生的。第四步可将其降低15%。 - Sid
感谢提供额外的信息。 - Vinay Sajip
3个回答

17

stdlib logging 包为开发人员/运维人员/支持人员提供了很多灵活性和功能,但这种灵活性显然是有代价的。如果性能需求优先于灵活性,则需要选择其他方案。您是否按照文档中描述 优化步骤?在合理的硬件上,典型的日志调用需要几十微秒的时间,这似乎并不过分。但是,在紧密循环中记录日志往往是不明智的,仅因为生成的信息量可能需要太长时间才能浏览。

查找调用者的代码可能非常昂贵,但如果您想要例如文件名和行号,那么就是必需的。

QueueHandler 适用于日志 I/O 将花费很长时间且无法在带内完成的情况。例如,需要将 Web 应用程序的日志通过电子邮件发送给站点管理员,不能冒险直接使用 SMTPHandler,因为电子邮件握手可能很慢。

不要忘记,在Python中进行线程上下文切换是很慢的。你尝试过SocketHandler吗?在文档中有一个合适的起点,可以启动一个单独的接收进程来执行实际的文件、电子邮件等I/O操作。这样,你的进程只需要进行套接字I/O,而不必仅仅为了记录日志而进行上下文切换。使用域套接字或UDP可能更快,尽管后者当然会有丢失。

还有其他优化方式。例如,日志记录中的标准处理程序在emit()周围进行锁定,以保证线程安全 - 如果在你控制下的特定情况下没有处理程序的争用,你可以有一个处理程序子类,它不会执行锁定获取和释放等操作。等等。


2
谢谢你的建议。我同意灵活性肯定是有代价的。我尝试了以下几个方案:
  1. 实现了SocketHandler和Unix DataGram Handler。它们都使时间增加了三倍。我想这是因为pickling。
  2. 做了一些页面上提到的性能优化。
  3. 在StreamHandler的emit中尝试了无锁日志记录。
  4. 尝试每100次调用刷新一次,而不是每次调用都刷新。

2,3,4都有所帮助,其中#4效果最好。

- Sid

9
如果你想得到更好的答案,请尽可能详细地描述问题,为什么需要记录如此大量的消息?日志记录是设计用于记录重要信息,特别是警告和错误,并不是你执行的每一行代码。
如果日志记录占用了超过1%的处理时间,很可能你在错误使用它,而这并不是日志记录的错。
其次,与性能相关:不要在将消息发送到日志记录模块之前构建消息(使用格式化命令参数替换格式%参数)。这是因为日志记录会为你完成这项工作,而且速度更快。

谢谢,你的第二个提示很有帮助。至于具体问题,我只是在寻找Python中用于延迟敏感应用程序的最佳性能日志记录选项。我明白我贴出的代码并不实用,但它的唯一目的是基准测试。 - Sid

1

Python在传统意义上并非真正的多线程。每当一个线程执行时,它必须拥有全局解释器锁(GIL)。"线程"在调用系统或等待IO时会产生yield。这允许解释器线程运行其他Python "线程"。这相当于异步I/O。

无论日志消息的结果是使用还是丢弃,都会完成评估日志消息参数的所有工作。如其他回复中所述。 然而,被忽略的一点是(这也是你提到多线程的地方),由于现代计算机具有许多核心,因此写入大量数据到磁盘可能会很慢,但将输出写入文件的过程将分配给另一个核心,而解释器则继续处理另一个Python "线程"。操作系统将完成异步磁盘写入,实际的磁盘写入时间几乎为零。

只要解释器始终有另一个线程可以切换,就不会浪费任何时间进行写入。除非您真的超负荷使用磁盘,否则解释器只会在所有Python "线程"都被阻塞在I/O上时才真正浪费时间。


网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接