【问题标题】:Why don’t I see interleaved lines when writing to a file in parallel?为什么我在并行写入文件时看不到交错行?
【发布时间】:2013-12-17 12:30:17
【问题描述】:

我有一个运行多个 Python 进程的 Red Hat Enterprise Linux 系统。每个进程都通过标准 Python WatchedFileHandler 写入同一个日志文件。他们一起每秒写几十个条目。平均条目长度约为 200 字节,有时更长。

我相信我应该在该文件中混淆(交错)条目。但我似乎没有找到任何东西。为什么?操作系统是否保证低于阈值长度的数据?我可以找到有关管道和 FIFO 的提及 (PIPE_BUF),但不是常规文件。或者对于我在典型系统上的负载来说,竞争条件太窄了?

【问题讨论】:

    标签: python linux concurrency io


    【解决方案1】:

    来自文档:

    http://docs.python.org/2.7/library/logging.handlers.html#watchedfilehandler

    WatchedFileHandler 类,位于 logging.handlers 模块中, 是一个 FileHandler,它监视它正在记录的文件。如果文件 更改后,它会关闭并使用文件名重新打开。

    WatchedFileHandler 适用于 Linux,但不适用于 Windows(因为它没有 inode)。它监视文件 inode 上的更改。如果对该文件进行了任何更改,则会将其关闭并再次打开。

    根据 WatchedFileHandler 的实现方式,我认为他们会重复此过程,直到它可以安全地写入文件,但这可能意味着您的进程一直在为日志文件打开/关闭。

    更正:它尝试关闭一次,然后再次重新打开文件。我正在寻找另一种解释,说明为什么您没有遇到问题。

    到目前为止,我没有找到任何理由来解释为什么您的日志中没有混合行。 WatchedFileHandler 旨在供一个应用程序使用(在发出之前使用 RLock 控制多线程访问,但有一个有价值的例外是支持外部更改,例如日志轮换)。但是查看它的超类的源码,我没有找到任何原因。一个未经检验的理论是:

    a) 因为日志总是以附加模式打开

    b) 因为它在写入之前检查一次,是否有任何变化

    c) 你总是得到一个完整的行,因为你的行小于写入缓冲区。所以你从最后一行的末尾开始,写一个新行,这个过程一次又一次地重复。如果两个进程同时写,它们将从最后一行的末尾开始写新的行。

    尝试查找日志行上的异常情况,例如缺少行...如果日志的大小非常规则,则可能难以检查并发问题。我也会在日志的最后一行查找异常情况。

    您的系统有多少个处理器?

    破解日志的测试程序:

    import logging
    import logging.handlers
    import sys
    
    FORMAT = "%(asctime)-15s %(process)5d %(message)s"
    
    logger = logging.getLogger(__name__)
    wfh = logging.handlers.WatchedFileHandler("test.log", "a")
    wfh.setFormatter(logging.Formatter(FORMAT))
    logger.addHandler(wfh)
    logger.setLevel(logging.DEBUG)
    
    n = int(sys.argv[1])
    
    for x in range(1000):
            logger.info("%6d %s" % (x, str(n)*(4096+n)))
    

    使用简单的 shell 脚本运行:

    python test.py 1 &
    python test.py 2 &
    python test.py 3 &
    python test.py 4 &
    python test.py 5 &
    python test.py 6 &
    python test.py 7 &
    python test.py 8 &
    python test.py 9 &
    

    在具有 4 个处理器的 CentOS 6.3 上运行,我开始看到线路异常。可以在程序中改变线条的大小,小线条看起来还可以,大线条就不行了。

    您可以通过以下方式进行测试:

     grep -v ^2013 test.log
    

    如果日志没问题,所有行都以 2013 开头。grep 不会列出混合行,但我可以用 less 轻松找到它们。

    因此,它对您有用,因为您的行小于写入缓冲区,或者因为您的进程不经常写入日志,但即使是它们,也不能保证它会一直有效。

    【讨论】:

    • 我很确定这是指文件元数据的变化,特别是 inode,它发生在轮换中。每次写入后重新打开日志文件会很奇怪;它也不保证原子性。如果没有其他参考资料,恐怕您的回答将无济于事。
    • 其实可以在源码中看到:Lib/logging/handlers.py:462.
    • 我认为您的附加模式参考是朝着正确方向迈出的一步。在此处查看O_APPEND 的讨论:stackoverflow.com/questions/10650861/…
    • 我仍然没有清晰的画面,但我接受这个答案,因为它很有帮助并且听起来接近事实,谢谢。
    【解决方案2】:

    更新:

    虽然在多线程环境中使用日志记录是安全的:

    日志模块是线程安全的,没有任何特殊的 需要由其客户完成的工作。它通过使用实现了这一点 线程锁;有一个锁可以序列化对模块的访问 共享数据,并且每个处理程序还创建一个锁来序列化访问 到它的底层 I/O。

    http://docs.python.org/2/library/logging.html#thread-safety

    它在多处理环境中似乎是有风险的,因为它不使用文件锁保护日志文件(它用于保护的只是一堆互斥锁)。请参阅 FileHandler 类的source code(由 WatchedFileHandler 使用)。为了保证写入原子性,您必须自己使用文件锁来保护您的日志文件,或者您可以使用类似ConcurrentLogHandler

    所以您很幸运地避免了日志文件中的数据重叠。通常操作系统不提供任何关于写入原子性的保证,而且不同版本的 libc 可能有不同的缓冲区大小默认值。

    您可以使用以下 C 代码获取系统上的默认流缓冲区大小

    #include <stdio.h>
    
    int main(void)
    {
        printf("%d\n", BUFSIZ);
        return 0;
    }
    

    【讨论】:

    • 请重新阅读我的问题。我有几个进程,而不是一个进程中的多个线程。
    • @VasiliyFaronov 通过简要查看源代码,我可以得出结论,我错了,日志记录不使用文件锁 => 在多进程环境中不安全。所以你很幸运地避免了数据重叠。一般来说,操作系统不保证你“写原子性”,每个 libc 可能有不同的内部缓冲区大小的默认值(afaik,这没有任何标准)。我想你必须自己用文件锁来保护你的文件。
    • 您可以将其发布为答案,如果没有其他人参与,我会接受。
    • 但如果您还可以提及典型 GNU libc 的“内部缓冲区大小”以及这些大小意味着什么保证(如果有的话),那就太好了。
    • 你能解释一下“流缓冲区大小”与我的问题有什么关系吗?
    猜你喜欢
    • 1970-01-01
    • 1970-01-01
    • 2020-10-01
    • 2022-10-23
    • 2019-08-01
    • 2019-12-30
    • 1970-01-01
    • 1970-01-01
    相关资源
    最近更新 更多