Python日志记录导致延迟？

Question

我正在使用Python3 + bottle/UWSGI开发实时REST API.我的代码遇到了延迟,有时是100秒,这在我的应用程序中很重要.

使用logging模块,我试图识别代码的慢速部分,打印单个代码块运行的时间.我知道这是一种非常糟糕的分析代码的方法,但有时它能够很好地完成这项工作.

即使我发现了一些缓慢的部分,我仍然遗漏了一些东西 - 单个部分似乎需要10秒的ms,但通常它们整体上需要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中添加,并在本文中进行了描述),并在单独的线程或进程中对日志记录事件进行I/O处理.

Answer 2

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

正如hasan所提出的,异步日志处理程序可以成为可行的方法.

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

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]

效果：

• 日志记录会非常快

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

• 通过每分钟左右记录一个带有丢弃条目数的单个条目（将丢弃的条目交换为零），可以很好地增强这一点。