摘要:原文在容器打印日志到控制台阻塞的排障的时候看到一个观点把日志打印到控制台要比打印到文件慢,而且是非常慢。那么为何输出到控制台慢有何办法加速呢问题要从三个角度来分别回答的角度程序角度容器角度角度写到控制台其实就是写到,更严格的说应该是。
原文
在容器打印日志到控制台阻塞的排障的时候看到一个观点:
把日志打印到控制台要比打印到文件慢,而且是非常慢。
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”:
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(" ") >= 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,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
文章版权归作者所有,未经允许请勿转载,若此文章存在违规行为,您可以联系管理员删除。
转载请注明本文地址:https://www.ucloud.cn/yun/73375.html
摘要:原文在容器打印日志到控制台阻塞的排障的时候看到一个观点把日志打印到控制台要比打印到文件慢,而且是非常慢。那么为何输出到控制台慢有何办法加速呢问题要从三个角度来分别回答的角度程序角度容器角度角度写到控制台其实就是写到,更严格的说应该是。 原文 在容器打印日志到控制台阻塞的排障的时候看到一个观点: 把日志打印到控制台要比打印到文件慢,而且是非常慢。 log4j2和logback的两个iss...
摘要:是指可能导致程序终止的非常严重的时间。具有最高的级别,旨在关闭中的日志功能。因此为每一个消息选择一个合适的日志级别是非常重要的。日志的个小建议将日志访日代码块它能显著的减少因为字符串拼接而带来的性能的影响。 前言 首先,这篇文章没有进行任何的日志功能的详细介绍,而是对日志提出了几种最佳实践。适合对日志记录有所了解的同学阅读。下面是正文: JAVA日志管理既是一门科学,又是一门艺术。科学...
摘要:为何选择引擎微信小游戏推出之后,很多公司也相应的进入到微信小游戏这个领域,现在市场上的游戏开发引擎,如都对小游戏有了很好的兼容性。 1. 为何选择Laya引擎 微信小游戏推出之后,很多公司也相应的进入到微信小游戏这个领域,现在市场上的游戏开发引擎,如Cocos、Egret、Laya都对小游戏有了很好的兼容性。目前公司技术栈主要是使用Cocos和Laya,经过几个项目的接触,考量了引擎在...
阅读 3563·2023-04-26 02:32
阅读 3697·2021-11-23 10:05
阅读 2261·2021-10-08 10:04
阅读 2657·2021-09-22 16:06
阅读 3584·2021-09-22 15:27
阅读 726·2019-08-30 15:54
阅读 1613·2019-08-30 13:50
阅读 2577·2019-08-29 13:56