4 个进程写同一个日志文件,我实测丢了 21.74% 的行
一个安静的问题
有个服务跑着跑着日志就断了。不是报错,是中间少了一截。日志文件在,进程在,没有异常栈。
我做了个最小复现:4 个进程,每个往同一个 RotatingFileHandler 写的日志文件里写 5000 行,总共应该落 20000 行。
结果落盘 15652 行,丢了 4348 行,占 21.74%。
丢的比例不固定,跑几次数字会变,但方向一致:一定是少的。
为什么
RotatingFileHandler 底层是普通文件句柄。每个进程各自打开一次文件,各自维护一个写指针。写入时用的是追加模式,单次 write() 在内核层面是原子的,所以行不会互相写坏。
问题出在缓冲区。日志先写进进程内的缓冲区,不是每次都落盘。四个进程各自缓冲、各自按自己的时机刷盘,缓冲区里的内容在进程还没来得及刷就退出时就丢了。20000 行的量不算大,丢两成很常见。
更麻烦的是轮转。当文件超过 maxBytes 时,handler 会做三件事:把旧文件改名、把新文件建出来、切换写指针。四个进程可能同时想做这件事,于是:
- 一个进程正在往旧文件写,另一个进程把它改名了
- 改名之后另一个进程又建了个同名的新文件,两个进程的写指针指向了不同的文件
- 有的数据写进了已经被改名的旧文件,有的写进了新文件,还有的在改名的瞬间丢失
我这次把 maxBytes 设得足够大(1 MB,没触发轮转),就是为了把「缓冲区丢数据」和「轮转竞态」两个原因分开。结果即使完全不轮转,也丢了 21.74%。
怎么确认你中招了
不用改代码,先查:
- 统计日志行数,和业务侧的处理条数对一下,差得多就是丢了
- 看是否有整段的时间戳区间消失(不是零星几行,是连片)
- 临时把 handler 换成只写控制台,跑一轮,如果行数对上了,就是文件写入的问题
如果每次丢的比例差不多,但绝对值随总量线性变化,基本可以确定是缓冲。
三种解法,按场景选
每个进程写自己的文件
最简单,也最稳。文件名带上进程号或实例 ID:
handler = RotatingFileHandler(
f'app-{os.getpid()}.log', maxBytes=10*1024*1024, backupCount=5
)
每个进程有自己的缓冲区自己的文件指针,没有任何共享,不会丢。代价是日志散在多个文件里,需要用 grep 加通配符汇总,或者后期收集。
容器环境里这个方案尤其合适,日志本来就要靠采集器汇总。
走队列,主进程统一写
标准库自带 QueueHandler 和 QueueListener:
import logging, logging.handlers, multiprocessing
queue = multiprocessing.Queue()
root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(logging.handlers.QueueHandler(queue))
listener = logging.handlers.QueueListener(
logging.handlers.RotatingFileHandler(
'app.log', maxBytes=10*1024*1024, backupCount=5
)
)
listener.start()
子进程只管往队列里塞记录,主进程里的 listener 负责写文件。写文件的动作被串行化了,缓冲也只有一份。
要注意 QueueListener.start() 是个阻塞调用,要放在主进程的主线程里,或者放独立进程里跑。
用带进程锁的第三方 handler
concurrent-log-handler 这个包提供了 ConcurrentRotatingFileHandler,它在轮转时用文件锁保证只有一个进程在改文件名。实测有效,但引入了一个额外依赖,而且文件锁在某些网络文件系统上不可靠。
如果项目不想加依赖,我更倾向第一个方案。
顺便说一个反直觉的点
有人会说「加个 threading.Lock 不就解决了」。不行。
logging 模块内部的那把锁只保护 handler 实例自身状态(流对象、formatter 缓存),它不跨进程。四个进程各有自己的 handler 实例,加了锁也还是四把锁。跨进程同步得用文件锁或者消息队列。
一句话
多进程写同一个日志文件,我实测丢了两成行,而且不触发轮转也丢。根本原因是每个进程各有一份缓冲区。要么每个进程写自己的文件,要么用 QueueHandler 让主进程统一落盘。
- 点赞
- 收藏
- 关注作者
评论(0)