容器明明在跑,docker logs 却是空的?多半是 stdout 被缓冲了。这篇用一个每秒 print 一次的 Python 脚本,量出不同写法下日志出现的时间,并测出缓冲区大约多大。
默认(不是 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。
每 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)是否缓冲,我没有测。