关于java代码打包成jar在控制台运行变慢的问题

最近一直在实现一款类似JVM的虚拟机，在实现协程阶段进行了一些测试，同时和GO语言的协程执行效率进行了对比。

同样的代码 在ECLIPSE DEBUG状态下，我自己写的虚拟机执行需要9s，GO用vsCode编译成本地文件之后执行需要15s。

这样的结果，还比较满意，但是当把虚拟机项目打包成jar之后，执行完成需要50s...

后来找了多方原因大致问题如下

 

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

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