为何把日志打印到控制台很慢? - 颇忒脱 - SegmentFault 思否

标签: | 发表时间:2020-01-30 22:39 | 作者:
出处:https://segmentfault.com

原文

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

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

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

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

  1. linux的 stdout角度
  2. Java程序角度
  3. docker容器角度

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,对于大多数程序来说这不会造成瓶颈。

参考文档

相关 [日志 打印 控制台] 推荐:

为何把日志打印到控制台很慢? - 颇忒脱 - SegmentFault 思否

- -
容器打印日志到控制台阻塞的排障的时候看到一个观点:. 把日志打印到控制台要比打印到文件慢,而且是非常慢. log4j2和logback的两个issue官方也提到了这一点(见. stdout,更严格的说应该是. Can it be sped up?,这回答提到. 打印到stdout慢是因为终端的关系,换一个快速的终端就能提升.

Firebug控制台详解

- boho - 阮一峰的网络日志
Firebug是网页开发的利器,能够极大地提升工作效率. 我曾经翻译过一篇《Firebug入门指南》,介绍了一些基本用法. 控制台(Console)是Firebug的第一个面板,也是最重要的面板,主要作用是显示网页加载过程中产生各类信息. Firebug内置一个console对象,提供5种方法,用来显示信息.

fbv: 控制台图片查看器

- Grotteschi - LinuxTOY
fbv 是一款基于 framebuffer 的图片查看器,可以在真正的终端下查看 png/gif/jpeg/bmp 图片. 按 Ctrl-Alt-F1~F6 中的某一个键切换到终端,登录. 如果图片太大,使用 F 切换原大小/适合屏幕. 如果图片太大,也使用方向键或者 WAXD 滚动. 如果给定了多个文件,, 和.

优秀的控制台IRC客户端

- - Solidot
Ron Jones 写道 "Internet Relay Chat(IRC)是一种即时聊天和同步会议形式,主要作为一种群内交流方式使用. IRC的发明者是Jarkko Oikarinen(aka WiZ),当时他正受雇于芬兰奥卢大学. IRC是Linux社区必不可少的通信工具,可以让用户和开发者直接交流.

逆向打印机

- xiaonan - 创意酷
  一般来说,我们使用的打印机都是打印出油墨和字体的. 但是现在打印机被设计师的逆向思维改成了一个先进的概念. 那就是类似祛斑或者净化污渍一样的概念,把用过的A4纸放进新型逆向打印机,它将把黑色的油墨去掉,还你一张干净的白纸. 设计师还提出了利用激光将墨水去掉的技术. 这样的方式将是一个更简单的对纸品回收利用.

C# 中打印、预览、打印机设置和打印属性的方法

- Bloger - 博客园-首页原创精华区
   //获取或设置一个值,该值指示是否发送到文件或端口.    //设置打印时横向还是纵向.    openFileDialog1.Filter = "Text Files (*.txt)|*.txt";//打开文本的类型.    //获取文件对话框的初始目录(StartupPath)获得bin文件下的文件.

js打印局部内容

- - JavaScript - Web前端 - ITeye博客
已有 0 人发表留言,猛击->> 这里<<-参与讨论. —软件人才免语言低担保 赴美带薪读研.

日志管理

- - CSDN博客系统运维推荐文章
#很关键 [root@client01 ~]# ls /var/log/ anaconda.ifcfg.log. tallylog #关键日志,大部分记录在里面 [root@client01 ~]# ls /var/log/messages /var/log/messages. [root@client01 ~]# ps -ef|grep log #系统日志服务 root.

日志优化

- - 互联网 - ITeye博客
在任何系统中,日志都是非常重要的组成部分,它是反映系统运行情况的重要依据,也是排查问题时的必要线索. 绝大多数人都认可日志的重要性,但是又有多少人仔细想过该怎么打日志,日志对性能的影响究竟有多大呢. 今天就让我们来聊聊Java日志性能那些事. 说到Java日志,大家肯定都会说要选择合理的日志级别、合理控制日志内容,但是这仅是万里长征第一步……哪怕一些 DEBUG级别的日志在生产环境中不会输出到文件中,也可能带来不小的开销.

云时代的打印机,能够随时随地云打印

- 见涛 - 果壳网 guokr.com - 果壳网
在云计算盛行的年代,越来越多的产品和服务都被冠上了云的名号,云打印就是其中之一. 在以前要随时随地实现打印功能,无异于幻想,就像实现在这台电脑上复制,在另外一台电脑上粘贴一样,多好的电脑都不行. 最终还是谷歌先提出了有关云打印的概念,惠普紧随其后,在一年前发布了支持云打印(ePrint)的一系列打印机,云打印原理是给与支持云打印的打印机一个随机生成的12位邮箱地址,用户只要将需要打印的文档发送至邮箱中,就可以在打印机上将邮件或者附件打印出来.