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

原文在容器打印日志到控制台阻塞的排障的时候看到一个观点：把日志打印到控制台要比打印到文件慢，而且是非常慢。log4j2和logback的两个issue官方也提到了这一点（见LOG4J2-2239、LOGBACK-1422）。那么为何输出到控制台慢？有何办法加速呢？问题要从三个角度来分别回答：linux的stdout角度Java程序角度docker容器角度stdout角度写到控制台其实就是写到stdout，更严格的说应该是fd/1。Linux操作系统将fd/0、fd/1和fd/2分别对应stdin、stdout和stdout。那么问题就变成为何写到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”:StreamTypeBehaviorstdininputline-bufferedstdout (TTY)outputline-bufferedstdout (not a TTY)outputfully-bufferedstderroutputunbuffered那也就是说当stdout指向一个终端的时候，它采用的是line-buffered策略，而终端的处理速度直接影响到了性能。同时也给了我们另一个思路，不将stdout指向终端，那么就能够用到fully-buffered，比起line-buffered能够带来更大提速效果（想想极端情况下每行只有一个字符）。我写了一段小代码来做测试（gist）。先试一下stdout指向终端的情况：$ javac ConsolePrint.java$ java ConsolePrint 100000…lines: 100,000System.out.println: 1,270 msfile: 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 msfile: 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.out是PrintStream类型，下面是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; }}可以看到：System.out使用的缓冲大小仅为128字节。大部分情况下够用。System.out开启了autoFlush，即每次write都会立即flush。这保证了输出的及时性。PrintStream的所有方法加了同步块。这避免了多线程打印内容重叠的问题。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,000System.out.println: 2,563 msfile: 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，对于大多数程序来说这不会造成瓶颈。参考文档Standard output (stdout)Stdout Buffering