【问题标题】：Python logging causing latencies?Python日志记录导致延迟？
【发布时间】：2014-09-07 14:35:22
【问题描述】：

我正在使用 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 模块中......

【问题讨论】：

我怀疑是系统问题而不是代码问题。例如，如果您在 ubuntu 上并且没有定义交换文件，或者如果您在 Windows 上并且您的硬盘驱动器上的空间小于 20GB，您将体验到响应能力的损失
如果您可以将其简化为显示问题的小型独立脚本，请发布。否则，很难看到多线程环境中发生了什么。您能否确定在您的系统中（例如在第三方库中）anywhere 中没有定义同步处理程序？这可能会影响延迟。除了NullHandler，库不应该添加处理程序，但开发人员并不总是按照他们应该做的事情。
另请注意，basicConfig() 的 format= 参数仅适用于在该调用中添加的处理程序，即在这种情况下适用于 QueueHandler。这不使用格式化程序，StreamHandler 不会设置格式化程序，因为它只传递给 QueueListener。您需要明确设置格式化程序。
@VinaySajip 你说得对，这是由 UWSGI 的“神奇”进程分叉引起的。当我打印当前使用的处理程序时，QueueHandler 消失了，默认的StreamHandler 再次出现。我现在正在尝试使用延迟初始化来在进程分叉后创建处理程序。

标签： python performance logging latency

【解决方案1】：

您可以使用异步处理程序（QueueHandler 和相应的QueueListener，在 Python 3.2 中添加，并在 this post 中进行了描述）并在单独的线程或进程中对日志事件进行 I/O 处理。

【讨论】：

似乎它完全解决了我的问题！我刚刚将它投入生产，日志记录延迟似乎消失了。此外，我只需要进行少量编程即可修复它。非常感谢！
哦，不，高兴得太早了，同样的延迟再次出现，所以我的问题仍未解决:(
最后，我已经正确实现了一切，包括进程分叉后记录器的延迟初始化，并且延迟真的消失了。您的回答从一开始就是正确的，只是 UWSGI 的混乱导致了所有的并发症。

【解决方案2】：

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

正如 hasan 所提议的，异步日志处理程序可能是要走的路。

最近我尝试使用Logbook，可以说，它会为您提供所需的一切 - ZeroMQHandler 以及 ZeroMQSubscriber

【讨论】：

老实说，4 年后，我们根据您最初的建议在 Logbook 上到处运行，只是没能把它写在这里 :) 它工作得很好，问题再也没有出现过，所以你的回答是对的！
LogBook 如何进行异步日志记录？我在他们的文档中找不到与此相关的任何信息
@SarimMehdi LogBook ZeroMQHandler 将日志记录发送到 ZeroMQ 套接字并继续，日志的实际写入（如果有的话）异步发生 - 如果您使用 ZeroMQSubscriber 收集记录并对其进行处理。无论如何，这个 async 绝不是 asyncio。

【解决方案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]

效果：

记录会非常快
如果您的登录速度快于写入驱动器的速度，则较旧的未写入条目将被静默丢弃。
通过记录单个条目以及每分钟左右丢弃条目的数量（将丢弃的条目交换为零）来增强这一点可能会很好。

【讨论】：

super().put(item, block=False) 后面缺少一个break 命令
嘿，埃里克，干得好，干得好！。 6 个月前，@PhilippeRemy 在您的工作中强调了一个非常重要的警告，但您对此视而不见。请问，我们能知道为什么吗？

【解决方案4】：

这可能取决于日志处理程序。我的经验是，例如用作日志处理程序的 PostgreSQL 在速度方面是一个非常糟糕的选择。 FileHandler 可能会给你很好的结果，但如果你的系统 I/O 很重，那么即使是简单的文件写入也会很慢。我建议使用一些异步处理程序，例如通过 UDP 将日志发送到专用进程。

【讨论】：