Python日志导致延迟？
我正在用Python3和Bottle/UWSGI开发一个实时的REST API。在我的代码中，我遇到了一些延迟，有时候达到100毫秒，这对我的应用来说是很重要的。
我使用了logging模块，试图找出代码中慢的部分，打印每个代码块运行所需的时间。我知道这种方法并不是很专业，但有时候它能帮我找到问题。
虽然我找到了几个慢的部分，但我还是觉得缺少了什么——单独的部分看起来只需要十几毫秒，但整体上却经常需要几百毫秒。经过一系列让我几乎抓狂的实验，我得出了以下结论：
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模块上……
4 个回答
这可能跟你使用的日志处理方式有关。我个人的经验是，比如说用PostgreSQL作为日志处理方式，速度非常慢，不太适合。用FileHandler可能效果会好很多，但如果你的系统经常进行大量的输入输出操作，即使是简单的文件写入也可能会变得很慢。我建议使用一些异步的处理方式，比如通过UDP把日志发送到一个专门的进程去处理。
首先，开始使用一个驱逐队列（循环缓冲区）……这样可以确保队列处理程序不会占用所有可用的内存。
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]
效果：
日志记录会非常快
如果你记录的速度比写入硬盘的速度快，旧的未写入的记录会被悄悄丢弃。
可以考虑每分钟记录一次丢弃的记录数量，来增强这个功能（将丢弃的数量重置为零）。
你可以使用异步处理程序（比如QueueHandler和相应的QueueListener，这些是在Python 3.2中新增的，详细介绍可以参考这篇文章）来在一个单独的线程或进程中处理你的日志事件的输入输出。
试试Logbook提供的异步日志记录
正如hasan所提到的，使用异步日志处理器可能是个不错的选择。
最近我尝试使用了Logbook，可以说它能提供你所需要的一切——包括ZeroMQHandler和ZeroMQSubscriber。