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 成功地一次写完了所有东西。没有普遍保证是这种情况，这就是为什么文档不 promise 这会起作用的原因。

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

write(fd, buf, buflen);

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

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

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