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 模块中......

Answer 1

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