Python multiprocessing+logging.FileHandler

Question

我正在尝试在多进程服务器中实现日志记录。根据文档，“不支持从多个进程记录到单个文件”。我已经创建了一个小程序来检查以下语句：

import logging
import multiprocessing
import os

log = logging.getLogger()


def setup_logger():
    formatter = logging.Formatter('%(asctime)s %(name)s %(levelname)s: %(message)s')

    fileHandler = logging.FileHandler('test.log')
    fileHandler.setFormatter(formatter)

    log.setLevel(logging.DEBUG)
    log.addHandler(fileHandler)


def write_log_entries(identifier, start_event):
    start_event.wait()
    for i in range(100):
        s = ''.join(str(identifier) for k in range(30))
        log.info('[{}, {}] --- {}'.format(os.getpid(), identifier, s))


if __name__ == '__main__':
    setup_logger()
    procs = []
    start_event = multiprocessing.Event()
    for i in range(100, 300):
        p = multiprocessing.Process(target=write_log_entries, args=(i, start_event))
        procs.append(p)

    for p in procs:
        p.start()

    start_event.set()

    for p in procs:
        p.join()

执行完上面的代码后，我本以为"test.log“中会出现一片混乱，但实际上一切似乎都很好(当然，除了时间戳，因为时间戳并没有按顺序排列)。

有人能解释一下，当多个进程同时写入日志文件时，为什么日志条目不会重叠吗？在这种情况下，log.info()可以被认为是原子的吗？

Answer 1

简而言之:内核锁定了对write的单个调用，所以只要消息很小就没问题，所以它们会在单个write中刷新，并且这个write可以一次成功地写入所有内容。没有一般的保证是这样的，这就是为什么文档根本没有承诺这将会起作用。

冗长的答案:每次调用log.info都会刷新日志输出。这是必要的，否则您将无法看到文件中的最新日志条目。在Python/libc级别上，flush被实现为对write(2) syscall的调用，该syscall被调用以写出文件缓冲区的内容。在您的示例中，缓冲区内容是您的日志消息。因此，Python或libc根据使用的文件，最终调用操作系统调用，如下所示：

write(fd, buf, buflen);

...where fd是日志文件的系统级文件描述符，buf是缓冲写入的内存，buflen是消息的长度。(如果您使用strace之类的工具跟踪Python进程，就会看到这些调用。) write返回成功写入的字符数，内核不会将这些字符与文件同一区域中的其他写入交错。如果文件是在O_APPEND模式下打开的，那么写操作甚至可以保证在文件的末尾，至少在Unix上是这样。因此，如果buflen很小，就像正常的日志消息一样，一切都很好。但至少有两件事会出错。

首先，不能保证在一个write中写出所有的buflen。write可以被信号中断，fd可以指向接受固定大小写入的设备，或者您的日志消息可能足够大，内核不会接受单个区块。通常，这不是问题--正确编写的write总是以循环的形式实现的。但在您的情况下，这将是一场灾难，因为对write的不同调用将与其他进程交错。

其次，如果您的日志消息足够大，无法放入stdio缓冲区(8K左右)，那么它将在到达内核之前被拆分成块。在记录回溯日志或将日志格式化为详细格式(如XML )时，很容易发生这种情况。