为何把日志打印到控制台很慢?

栏目: 编程工具 · 发布时间: 5年前

内容简介:在把日志打印到控制台要比打印到文件慢,而且是非常慢。

原文

容器打印日志到控制台阻塞的排障 的时候看到一个观点:

把日志打印到控制台要比打印到文件慢,而且是非常慢。

log4j2和logback的两个issue官方也提到了这一点(见 LOG4J2-2239LOGBACK-1422 )。

那么为何输出到控制台慢?有何办法加速呢?问题要从三个角度来分别回答:

stdout

stdout 角度

写到控制台其实就是写到 stdout ,更严格的说应该是 fd/1 。Linux操作系统将 fd/0fd/1fd/2 分别对应 stdinstdoutstdout

那么问题就变成为何写到 stdout 慢,有何优化办法?

造成 stdout 慢的原因有两个:

stdout
stdout

在SO的这个问题中: Why is printing to stdout so slow? Can it be sped up? ,这回答提到 打印到stdout慢是因为终端的关系,换一个快速的终端就能提升 。这解释了第一个原因。

stdout 本身的缓冲机制是怎样的? Stdout Buffering 介绍了glibc对于stdout缓冲的做法:

  • stdout 指向的是终端的时候,那么它的缓冲行为是 line-buffered ,意思是如果缓冲满了或者遇到了newline字符,那么就flush。
  • stdout 没有指向终端的时候,那么它的缓冲行为是 fully-buffered ,意思是只有当缓冲满了的时候,才会flush。

其中缓冲区大小是4k。下面是一个总结的表格“

GNU libc (glibc) uses the following rules for buffering”:

Stream Type Behavior
stdin input line-buffered
stdout (TTY) output line-buffered
stdout (not a TTY) output fully-buffered
stderr output unbuffered

那也就是说当 stdout 指向一个终端的时候,它采用的是 line-buffered 策略,而终端的处理速度直接影响到了性能。

同时也给了我们另一个思路,不将 stdout 指向终端,那么就能够用到 fully-buffered ,比起 line-buffered 能够带来更大提速效果(想想极端情况下每行只有一个字符)。

我写了一段小代码来做测试( gist )。先试一下 stdout 指向终端的情况:

$ javac ConsolePrint.java
$ java ConsolePrint 100000
...
lines: 100,000
System.out.println: 1,270 ms
file: 72 ms
/dev/stdout: 1,153 ms

代码测试了三种用法:

  • System.out.println 指的是使用 System.out.println 所花费的时间
  • file 指的是用4k BufferedOutputStream 写到一个文件所花费的时间
  • /dev/stdout 则是同样适用4k BufferedOutputStream 直接写到 /dev/stdout 所花费的时间

发现写到文件花费速度最快,用 System.out.println 和写到 /dev/stdout 所花时间在一个数量级上。

如果我们将输出重定向到文件:

$ java ConsolePrint 100000 > a
$ tail -n 5 a
...
System.out.println: 920 ms
file: 76 ms
/dev/stdout: 31 ms

则会发现 /dev/stdout 速度提升到 file 一个档次,而 System.out.println 并没有提升多少。之前不是说 stdout 不指向终端能够带来性能提升吗,为何 System.out.println 没有变化呢?这就要 Java 对于 System.out 的实现说起了。

Java程序角度

下面是 System 的源码:

public final static PrintStream out = null;
...
private static void initializeSystemClass() {
  FileOutputStream fdOut = new FileOutputStream(FileDescriptor.out);
  setOut0(newPrintStream(fdOut, props.getProperty("sun.stdout.encoding")));
}
...
private static native void setOut0(PrintStream out);
...
private static PrintStream newPrintStream(FileOutputStream fos, String enc) {
  ...
  return new PrintStream(new BufferedOutputStream(fos, 128), true);
}

可以看到 System.outPrintStream 类型,下面是 PrintStream 的源码:

private void write(String s) {
  try {
    synchronized (this) {
      ensureOpen();
      textOut.write(s);
      textOut.flushBuffer();
      charOut.flushBuffer();
      if (autoFlush && (s.indexOf('\n') >= 0))
        out.flush();
    }
  } catch (InterruptedIOException x) {
    Thread.currentThread().interrupt();
  } catch (IOException x) {
    trouble = true;
  }
}

可以看到:

  1. System.out 使用的缓冲大小仅为128字节。大部分情况下够用。
  2. System.out 开启了autoFlush,即每次write都会立即flush。这保证了输出的及时性。
  3. PrintStream 的所有方法加了同步块。这避免了多线程打印内容重叠的问题。
  4. PrintStream 如果遇到了newline符,也会立即flush(相当于 line-buffered )。同样保证了输出的及时性。

这解释了为何 System.out 慢的原因,同时也告诉了我们就算把 System.out 包到BufferedOutputStream里也不会有性能提升。

Docker容器角度

那么把测试代码放到 Docker 容器内运行会怎样呢?把gist里的Dockerfile和ConsolePrint.java放到同一个目录里然后这样运行:

$ docker build -t console-print .
$ docker run -d --name console-print console-print 100000
$ docker logs --tail 5 console-print
...
lines: 100,000
System.out.println: 2,563 ms
file: 27 ms
/dev/stdout: 2,685 ms

可以发现 System.out.println/dev/stdout 的速度又变回一样慢了。因此可以怀疑 stdout 使用的是 line-buffered 模式。

为何容器内的 stdout 不使用 fully-buffered 模式呢?下面是我的两个猜测:

  • 不论你是 docker run -t 分配 tty 启动,还是 docker run -d 不非配tty启动,docker都会给容器内的 stdout 分配一个 tty
  • 因为docker的logging driver都是以“行”为单位收集日志的,那么这个 tty 必须是 line-buffered

虽然 System.out.println 很慢,但是其吞吐量也能够达到~40,000 lines/sec,对于大多数程序来说这不会造成瓶颈。

参考文档


以上就是本文的全部内容,希望本文的内容对大家的学习或者工作能带来一定的帮助,也希望大家多多支持 码农网

查看所有标签

猜你喜欢:

本站部分资源来源于网络,本站转载出于传递更多信息之目的,版权归原作者或者来源机构所有,如转载稿涉及版权问题,请联系我们

精益思想

精益思想

(美)詹姆斯 P.沃麦克(James P.Womack)、(英)丹尼尔 T.琼斯(Daniel T.Jones) / 沈希瑾、张文杰、李京生 / 机械工业出版社 / 2011-4 / 48.00元

打算尝试精益的人,该怎么做? 已经实行精益的人,下一步怎么办? 本书包含了最新的精益理论、方法和工具,一一解答上述问题。 这是目前关于流程再造最好的书,也是最好读的。——《高业周刊》 本书中文简体字版由FreePress通过AiWA授权机械工业出版社在中国大陆独家出版发行。未经出版者书面许可,不得以任何方式抄袭、复制或节录本书中的任何部分。 《精益思想》于1996年秋......一起来看看 《精益思想》 这本书的介绍吧!

HTML 编码/解码
HTML 编码/解码

HTML 编码/解码

Markdown 在线编辑器
Markdown 在线编辑器

Markdown 在线编辑器

RGB HSV 转换
RGB HSV 转换

RGB HSV 互转工具