爲什麼把日誌打印到控制檯很慢？

原文

在容器打印日誌到控制檯阻塞的排障的時候看到一個觀點：

把日誌打印到控制檯要比打印到文件慢，並且是很是慢。

log4j2和logback的兩個issue官方也提到了這一點（見LOG4J2-2239、LOGBACK-1422）。

那麼爲什麼輸出到控制檯慢？有何辦法加速呢？問題要從三個角度來分別回答：

1. linux的stdout角度
2. Java程序角度
3. 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」:

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.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;
  }
}

能夠看到：

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，對於大多數程序來講這不會形成瓶頸。

參考文檔

• Standard output (stdout)
• Stdout Buffering