bigywater.tech
Docker · 73

容器日志延迟:程序 stdout 缓冲与 docker logs

容器明明在跑,docker logs 却是空的?多半是 stdout 被缓冲了。这篇用一个每秒 print 一次的 Python 脚本,量出不同写法下日志出现的时间,并测出缓冲区大约多大。

10.3 秒
默认 print 到管道时,docker logs 里第一行出现的时间(脚本约 10 秒后退出)
0.1~0.2 秒
加了 -u、PYTHONUNBUFFERED=1、flush=True 或 -t 之后第一行出现的时间
8100 字节
不 flush 时,第一批输出被写出时的累计字节数(缓冲区约 8 KiB)

现象

实测 · 本机执行输出
  默认(不是 TTY):第一行出现在 docker logs 里的时间 10.3 秒;第 3 秒时看到 0 行
  python -u:第一行出现在 docker logs 里的时间 0.2 秒;第 3 秒时看到 4 行
  PYTHONUNBUFFERED=1:第一行出现在 docker logs 里的时间 0.1 秒;第 3 秒时看到 4 行
  print(…, flush=True):第一行出现在 docker logs 里的时间 0.2 秒;第 3 秒时看到 4 行
  docker run -t(分配 TTY):第一行出现在 docker logs 里的时间 0.1 秒;第 3 秒时看到 4 行

stdout 接的是管道(docker 的日志管道)而不是终端时,Python 默认把输出攒在 8 KiB 左右的缓冲区里。短脚本退出时才一起写出,长期运行的服务可能很久看不到日志。

解决办法

实测 · 本机执行输出
  print 到 sys.stderr:第一行出现在 docker logs 里的时间 0.1 秒;第 3 秒时看到 3 行

python -u、环境变量 PYTHONUNBUFFERED=1、print(…, flush=True) 都有效。docker run -t 也能让它行缓冲,但会改变其它行为(比如合并 stdout 和 stderr),别随便为此加 -t。

stderr 与缓冲区

实测 · 本机执行输出
  每 0.02 秒输出一行 100 字节(每秒约 5000 字节),不 flush:第一次在 docker logs 里看到输出是 1.7 秒时,当时已有 8100 字节

stderr 默认不缓冲,所以错误信息常常比普通输出先出现。缓冲区大小我是从数据反推的:累计 8100 字节(81 行)时整块写出,与 8192 字节吻合。

对照

实测 · 本机执行输出
  sh 的 echo:第一行出现在 0.1 秒

sh 的 echo 每次直接 write,没有这个问题。别的语言(Node、Java、C 的 stdio、Ruby)是否缓冲,我没有测。

分步演示

stdout 缓冲
本步的对象

    本文用到的工具与边界

    • 本机 macOS 27 arm64 / Docker Desktop(Engine 29.8.2,容器跑在 Docker Desktop 自带的 Linux 虚拟机里,内核与宿主机的 macOS 不同);镜像为 linux/arm64;需要看虚拟机内部时用特权容器 + nsenter;计时用 time / date +%s%N,数字每次运行会有小幅抖动。脚本是 python:3.12-alpine 里的 python -c;第一行出现的时间由 Python 每 0.2 秒(第三节 0.02 秒)轮询 docker logs 得到,误差约 ±0.3 秒;每种情形运行一次;实验后已删除容器
    • 没有验证:Node / Java / Go / Ruby 的缓冲行为、C 程序的 stdio 缓冲与 stdbuf、管道里多个进程串联时的缓冲、Python 3.12 以外的版本、TTY 下的完整行为差异
    京ICP备2026067502号-1京公网安备11010502063487号