Python日志记录会导致延迟吗？

Question

我正在使用Python3+bottle/UWSGI开发实时REST API。我的代码中存在延迟，有时延迟长达100毫秒，在我的应用程序中这确实很重要。我使用logging模块尝试识别代码的慢部分，打印单个代码块运行所需的时间。我知道这是一个极其不精确的代码剖析方法，但有时它能够做好工作。尽管我已经确定了一些慢的部分，但仍然缺少某些东西 - 单独的部分似乎需要10毫秒的时间，但通常需要整体100毫秒。经过一些越来越疯狂的实验，几乎把我逼疯了，我得出了以下结论：

t = round(100*time.time())
logging.info('[%s] Foo' % t)
logging.info('[%s] Bar' % t)

令人惊讶的是，它给出了：

2014-07-16 23:21:23,531  [140554568353] Foo
2014-07-16 23:21:24,312  [140554568353] Bar

尽管这似乎难以置信，但是有两个连续的logging.info()调用，而且由于某种原因，它们之间几乎相差800毫秒。有人能告诉我发生了什么吗？值得注意的是，如果有多个info()调用，延迟只会在整个API方法中出现一次，并且最常见的情况是在其开头（第一个调用后）。我的唯一假设是磁盘延迟，同时运行着多个（但不是很多！）工作进程，并且我正在使用旋转磁盘，没有SSD。但我认为有缓冲区，而且操作系统会异步地为我执行磁盘刷新。我的假设是错误的吗？我应该避免完全记录以避免延迟吗？

编辑

根据Vinay Sajip的建议，我转换为以下初始化代码：

log_que = queue.Queue(-1)
queue_handler = logging.handlers.QueueHandler(log_que)
log_handler = logging.StreamHandler()
queue_listener = logging.handlers.QueueListener(log_que, log_handler)
queue_listener.start()
logging.basicConfig(level=logging.DEBUG, format="%(asctime)s  %(message)s", handlers=[queue_handler])

看起来它工作得很好（如果我注释掉queue_listener.start()，就没有输出），但是仍然会出现完全相同的延迟。我不明白这怎么可能，因为该调用应该是非阻塞的。我还在每个请求的末尾放置了gc.collect()以确保问题不是由垃圾收集器引起的 - 没有任何效果。我还尝试关闭整天的日志记录。延迟消失了，所以我认为它们的源头必须在logging模块中...

- Tregoreg

---

我会怀疑是系统问题而不是代码问题。例如，如果您使用的是Ubuntu并且没有定义交换文件，或者如果您使用的是Windows并且硬盘上的可用空间少于20GB，那么您将会遇到响应性丢失的问题。 - Jonathan Livni

如果您能将其简化为一个小的自包含脚本来展示问题，请发布它。否则，在多线程环境中很难看出发生了什么。您能确定系统中没有定义任何同步处理程序吗（例如第三方库）？这可能会影响延迟。库不应添加除“NullHandler”之外的其他处理程序，但开发人员并不总是按照他们应该做的事情去做。 - Vinay Sajip

还要注意，basicConfig() 中的 format= 参数仅适用于在该调用中添加的处理程序，即在此情况下的 QueueHandler。它不使用格式化程序，并且 StreamHandler 不会设置格式化程序，因为它只传递给 QueueListener。您需要显式地在其中设置格式化程序。 - Vinay Sajip

@VinaySajip 您是绝对正确的，这是由于UWSGI“神奇”的进程分叉引起的。当我打印当前使用的处理程序时，“QueueHandler”消失了，而默认的“StreamHandler”又出现了。我现在正在尝试使用延迟初始化，在进程分叉之后创建处理程序。 - Tregoreg

Answer 1

您可以使用异步处理程序(QueueHandler和对应的QueueListener，这些在Python 3.2中添加，并在此文章中进行了描述)，并在单独的线程或进程中执行日志事件的I/O处理。

- Vinay Sajip

---

看起来它完美地解决了我的问题！我刚刚将其投入生产，日志延迟似乎已经消失了。此外，我只需要进行少量编程即可修复它。非常感谢！ - Tregoreg

哦不，庆祝还为时过早，同样的延迟问题又出现了，所以我的问题仍未解决 :( - Tregoreg

最终，我已经正确地实现了所有内容，包括在进程分叉之后对记录器进行惰性初始化，延迟问题真正消失了。你一开始的答案就是正确的，只是与UWSGI搞混了，导致了所有的复杂情况。 - Tregoreg

Answer 2

尝试使用Logbook提供的异步日志记录

正如Hasan所建议的那样，异步日志处理程序可能是一种可行的方法。

最近我尝试使用Logbook，可以说，它将为您提供所有您需要的内容 - ZeroMQHandler 以及ZeroMQSubscriber

- Jan Vlcinsky

---

老实说，4年后我们在Logbook上到处奔跑，这都要归功于你最初的建议，只是没有在这里写下来 :) 它运行良好，问题再也没有出现过，所以你的答案是正确的！ - Tregoreg

LogBook如何进行异步日志记录？我在他们的文档中找不到任何相关信息。 - Muhammad Sarim Mehdi

@SarimMehdi LogBook的ZeroMQHandler将日志记录发送到ZeroMQ套接字并继续执行，实际的日志写入（如果有的话）是异步进行的 - 如果使用收集记录并对其进行某些操作的ZeroMQSubscriber。 无论如何，这种异步方式绝不是asyncio。 - Jan Vlcinsky

Answer 3

首先，从一个驱逐队列（循环缓冲区）开始……这可以确保队列处理程序无法消耗所有可用的RAM。

class EvictQueue(Queue):
    def __init__(self, maxsize):
        self.discarded = 0
        super().__init__(maxsize)

    def put(self, item, block=False, timeout=None):
        while True:
            try:
                super().put(item, block=False)
            except queue.Full:
                try:
                    self.get_nowait()
                    self.discarded += 1
                except queue.Empty:
                    pass

然后替换您根目录中的所有处理程序...在正常配置之后它们是什么...

def speed_up_logs(): 
    rootLogger = logging.getLogger()     
    log_que = EvictQueue(1000)
    queue_handler = logging.handlers.QueueHandler(log_que)
    queue_listener = logging.handlers.QueueListener(log_que, *rootLogger.handlers)
    queue_listener.start()
    rootLogger.handlers = [queue_handler]

效果:

• 日志记录将非常快速

• 如果您记录的速度比写入驱动器的速度快，那么未写入的较旧条目将被静默丢弃。

• 也许可以通过每隔一分钟记录一个单独的条目并显示已丢弃的条目数量（将其交换为零）来增强此功能。

- Erik Aronesty

---

在 super().put(item, block=False) 之后缺少一个 break 命令。 - Philippe Remy

嗨，Erik，干得好！6个月前，@PhilippeRemy在你的工作中指出了一个非常重要的警告，但你却置之不理。我们能知道原因吗？谢谢。 - Yahya

Answer 4

这可能取决于日志处理程序。我的经验是，例如将PostgreSQL用作日志处理程序会降低速度。FileHandler可能会给您非常好的结果，但如果您的系统非常I/O密集，则即使是简单的文件写入也可能很慢。我建议使用一些异步处理程序，例如通过UDP将日志发送到专用进程。

- hasan