如何避免后台IO高负载形成的长时间JVM GC停顿

译者注：其实本文的中心意思很是简单，没有耐心的读者建议直接拉到最后看结论部分，有兴趣的读者能够详细阅读一下。

原文发表于Linkedin Engineering，做者 Zhenyun Zhuang是Linkedin的一名Staff Software Engineer，联合做者Cuong Tran是Linkedin的一名Sr. Staff Engineer。

在咱们的生产环境中，咱们不断发现一些运行在JVM上的应用程序，偶尔会由于记录JVM的GC日志，而被后台的IO操做（例如OS的页缓存回写）阻塞，出现长时间的STW（Stop-The-World）停顿。在这些STW停顿的过程当中，JVM会暂停全部的应用程序线程，此时应用程序会中止对用户请求的响应，这对于要求低延迟的系统来讲，所以所致使的高延迟是不可接受的。

咱们的调查代表，致使这些停顿的缘由，是当JVM GC（垃圾回收）在写GC日时，因为write()系统调用所形成的。对于这些日志的写入操做，即便是采用异步写模式（例如，带缓存的IO或者非阻塞IO），仍然会被OS的页缓存回写等机制阻塞至关长的一段时间。

咱们将讨论解决这个问题的各类方式。对于要求低延迟的Java应用程序来讲，咱们建议将Java日志文件移动到一个单独的、或者高性能的磁盘驱动上（例如SSD，tmpfs）。

生产环境中的问题

当JVM管理的Java堆空间进行垃圾回收后，JVM可能会停顿，并对应用程序形成STW停顿。根据在启动Java实例时指定的JVM选项，GC日志文件会记录不一样类型的GC和JVM行为。

虽然某些由于GC致使的STW停顿（扫描/标记/压缩堆对象）已经被你们熟知，可是咱们发现后台IO负载也会形成长时间的STW停顿。在咱们的生产环境中曾经出现过，一些关键的Java应用程序发生许多没法解释的长时间STW停顿（> 5秒） 。这些停顿既不能从应用程序层的逻辑、也没法从JVM GC行为的角度加以解释。以下所示，咱们展现了一个超过4秒的长时间STW停顿，以及一些GC信息。当时咱们选择的垃圾回收器是G1。在一个只有8GB堆内存和使用并行Young Garbage Collection的G1环境下，垃圾回收一般不须要1秒便可完成，而且GC日志的影响也微乎其微。可是应用程序线程却停顿了超过4秒。全部GC完成的工做总量（例如，回收的堆大小）也没法解释这个长达4.17秒的停顿。

2015-12-20T16:09:04.088-0800: 95.743: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 8258M->6294M(10G), 0.1343256 secs]
2015-12-20T16:09:08.257-0800: 99.912: Total time for which application threads were stopped: 4.1692476 seconds
使用G1收集器时一次4.17秒的GC STW停顿

另外一个例子，下面的GC日志显示了另外一次11.45秒的STW停顿。此次使用的垃圾回收器是CMS（Concurrent Mark Sweep (译者注：原文中笔误写成了Concurrent Mode Sweep，已联系原做者修改)）。其中“user”/“sys”的时间几乎能够忽略，可是“real”表示的GC时间却超过了11秒。经过最后一行，咱们能够肯定应用程序发生了11.45秒的停顿。

2016-01-14T22:08:28.028+0000: 312052.604: [GC (Allocation Failure) 312064.042: [ParNew Desired survivor size 1998848 bytes, new threshold 15 (max 15) - age 1: 1678056 bytes, 1678056 total
: 508096K->3782K(508096K), 0.0142796 secs] 1336653K->835675K(4190400K), 11.4521443 secs] [Times: user=0.18 sys=0.01, real=11.45 secs] 2016-01-14T22:08:39.481+0000: 312064.058: Total time for which application threads were stopped: 11.4566012 seconds
使用CMS收集器时一次11.45秒的GC STW停顿

因为应用程序要求很是低的延迟，因此咱们花费了至关多的精力来调查这个问题。最后，咱们成功重现了这个问题，发现了根本缘由，以及相应的解决方案。

在实验环境中重现问题

对于这个致使没法解释的长时间JVM停顿的问题，咱们开始尝试在实验环境中重现它。为了使该过程可以获得更好的控制并重复重现，咱们设计了一个简单的压测程序，来代替复杂的生产环境应用程序。

咱们将在两个场景下运行这个压测程序：含有后台IO行为以及不含有后台IO行为。不含有后台IO的场景咱们称之为“基准线（baseline）”，而含有后台IO的场景用来重现问题。

Java压测程序

咱们这个Java压测程序只是不断地生成10KB的对象，并放到一个队列中。当对象数量达到100000时，会从队列中删除一半的对象。所以堆中存放的对象最大数量就是100000个，大概会占用1GB的空间。这个过程会持续一段固定的时间（例如5分钟）。

这个程序的源代码和后台IO的生成脚本，都位于https://github.com/zhenyun/JavaGCworkload。咱们考虑的主要性能指标是长时间JVM GC停顿的数量。

后台IO

后台IO咱们经过一个bash脚本，不断地复制大文件来模拟。后台程序会生成150MB/s的写入负载，可使一个普通磁盘的IO变得足够繁忙。为了更好理解生成的IO负载的压力大小，咱们使用“sar -d -p 2”来收集await（磁盘处理IO请求的平均时间（以毫秒计）），tps（每秒发往物理设备的传输总数）和wr_sec-per-s（写入设备的扇区数）。它们分别的平均数值为：await=421 ms, tps=305, wr_sec-per-s=302K。

系统准备



情景1 （不含后台IO负载）

运行基准线测试不须要有后台IO。全部JVM GC 停顿的时间序列数据以下图所示。没有观察到超过250ms的停顿。


情景1（不含后台IO负载）中全部的JVM GC 停顿

情景2 （含有后台IO负载）

当后台IO开始运行后，在只有5分钟的运行时间内，压测程序就出现了一次超过3.6秒的STW停顿，以及3次超过0.5秒的停顿！


情景2（含有后台IO负载）中全部的JVM GC 停顿

调查

为了了解是哪一个系统调用引发了STW停顿，咱们使用了strace来分析JVM实例产生的系统调用。

咱们首先确认了JVM将GC信息记录到文件，使用的是异步IO的方式。咱们又跟踪了JVM从启动后产生的全部系统调用。GC日志文件在异步模式下打开，而且没有观察到fsync()调用。

16:25:35.411993 open("gc.log", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3 <0.000073>
所捕获的用于打开GC日志文件的JVM系统调用open()

可是，跟踪结果显示，JVM发起的几个异步系统调用write()出现了不一样寻常的长时间执行状况。经过检查系统调用和JVM停顿的时间戳，咱们发现它们刚好吻合。在下图中，咱们分别对比展现了两分钟内系统调用和JVM停顿的时间序列。


时间序列对比（JVM STW停顿）


时间序列对比（系统调用write()）

咱们集中注意来看，位于13:32:35秒时最长达1.59秒的此次停顿，相应的GC日志和strace输出显示以下：


GC日志和strace输出

咱们来试着理解一下发生了什么。

1. 在35.04时（第2行），一次young GC开始了，而且通过0.12秒完成。
2. 此次young GC完成于时间35.17，而且JVM试图经过一次系统调用write()（第4行），将young GC的统计信息输出到gc日志文件中。
3. write()调用被阻塞了1.47秒，最后于时间36.64（第5行）完成，花费了1.47秒的时间。
4. 当write()调用于时间36.64返回JVM时，JVM记录下此次用时1.59秒的STW停顿（例如，0.12+0.47）（第3行）。

换句话说，实际的STW停顿时间包含两部分：（1） GC时间（例如，young GC）和 （2）GC记录日志的时间（例如， 调用write()的时间）。

这些数听说明，GC记录日志的过程发生在JVM的STW停顿过程当中，而且记录日志所用的时间也属于STW停顿时间的一部分。特别须要说明，整个应用程序的停顿主要由两部分组成：因为JVM GC行为形成的停顿，以及为了记录JVM GC日志，系统调用write()被OS阻塞的时间。下面这张图展现了两者之间的关系。


在记录GC日志过程当中JVM和OS之间的交互

若是记录GC日志的过程（例如write()调用）被OS阻塞，阻塞时间也会被计算到STW的停顿时间内。新的问题是，为何带有缓存的写入会被阻塞？在深刻了解各类资料，包括操做系统内核的源代码以后，咱们意识到带有缓存的写入可能被内核代码所阻塞。这里面有多重缘由，包括：（1）“stable page write”和（2）“journal committing”。

Stable page write: JVM对GC日志文件的写入，首先会使得相应的文件缓存页“变脏”。即便缓存页稍后会经过OS的回写机制被持久化到磁盘文件，可是在内存中使缓存页变脏的过程，因为“stable page write”仍然会受到页竞争的影响。在“stable page write”下，若是某页正处于OS回写过程当中，那么对该页的write()调用就不得不等待回写完成。为了不只有一部分新页被持久化到磁盘上，内核会锁定该页以确保数据一致性。

Journal committing: 对于带有日志（journaling）的文件系统，在写文件时都会生成相应的journal日志。当JVM向GC日志文件追加内容时，会产生新的块，所以文件系统则须要先将journal日志数据提交到磁盘。在提交journal日志的过程当中，若是OS还有其余的IO行为，则提交可能须要等待。若是后台的IO行为很是繁重，那么等待时间可能会很是长。注意，EXT4文件系统有一个“delayed allocation”功能，能够将journal数据提交延迟到OS回写后再进行，从而下降等待时间。还要注意的是，将EXT4的数据模式从默认的“ordered”改为“writeback”并不能解决这个问题，由于journal数据须要在write-to-extend调用返回以前被持久化。

后台IO行为

从JVM垃圾回收的角度来看，一般的生产环境都没法避免后台的IO行为。这些IO行为有几个来源：（1）OS活动；（2）管理和监控软件；（3）其余共存的应用程序；（4）同一个JVM实例的IO行为。首先，OS包含许多机制（例如，”/proc“文件系统）会引发向底层磁盘写入数据。其次，像CFEngine这样的系统级软件也会进行磁盘IO操做。第三，若是当前节点上还存在其余共享磁盘的应用程序，那么这些应用程序都会争抢IO。第四，除了GC日志以外，JVM实例也可能以其余方式使用磁盘IO。

解决方案

因为当前HotSpot JVM实现（包括其余实现）中，GC日志会被后台的IO行为所阻塞，因此有一些解决方案能够避免写GC日志文件的问题。

首先，JVM实现彻底能够解决掉这个问题。显然，若是将写GC日志的操做与可能会致使STW停顿的JVM GC处理过程分开，这个问题天然就不存在了。例如，JVM能够将记录GC日志的功能放到另外一个线程中，独立来处理日志文件的写入，这样就不会增长STW停顿的时间了。可是，这种采用其余线程来处理的方式，可能会致使在JVM崩溃时丢失最后的GC日志信息。最好的方式，多是提供一个JVM选项，让用户来选择适合的方式。

因为后台IO形成的STW停顿时间，与IO的繁重程度有关，因此咱们能够采用多种方式来下降后台IO的压力。例如，不要在同一节点上安装其余IO密集型的应用程序，减小其余类型的日志行为，提升日志回滚频率等等。

对于低延迟应用程序（例如须要提供用户在线互动的程序），长时间的STW停顿（例如>0.25秒）是不可忍受的。所以，必须进行有针对性的优化。若是要避免由于OS致使的长时间STW停顿，首要措施就是要避免由于OS的IO行为致使写GC日志被阻塞。

一个解决办法是将GC日志文件放到tmpfs上（例如，-Xloggc:/tmpfs/gc.log）。由于tmpfs没有磁盘文件备份，因此tmpfs文件不会致使磁盘行为，所以也不会被磁盘IO阻塞。可是，这种方法存在两个问题：（1）当系统崩溃后，GC日志文件将会丢失；（2）它须要消耗物理内存。补救的方法是周期性的将日志文件备份到持久化存储上，以减小丢失量。

另外一个办法是将GC日志文件放到SSD（固态硬盘，Solid-State Drives）上，它一般能提供更好的IO性能。根据IO负载状况，能够选择专门为GC日志提供一个SSD做为存储，或者与其余IO程序共用SSD。不过，这样就须要将SSD的成本考虑在内。

与使用SSD这样高成本的方案相比，更经济的方式是将GC日志文件放在单独一个HDD磁盘上。因为这块磁盘上只有记录GC日志的IO行为，因此这块专有的HDD磁盘应该能够知足低停顿的JVM性能要求。实际上，咱们以前演示的场景一就能够看作为这一方案，由于在记录GC日志的磁盘上没有任何其余的IO行为。

将GC日志放到SSD和tmpfs的评估

咱们采用了专有文件系统的解决方案，将GC日志文件分别放到SSD和tmpfs上。而后咱们按照场景二中的后台IO负载，运行了相同的Java压测程序。

对于SSD和tmpfs两者而言，咱们观察到了类似的结果，而且下图展现了将GC日志放到SSD磁盘上的结果。咱们注意到，JVM停顿的性能几乎能够与场景一相媲美，而且全部停顿都小于0.25秒。两者的结果均代表后台的IO负载没有影响到应用程序的性能。


将GC日志迁到SSD后的全部的JVM STW停顿

结论

有低延迟要求的Java应用程序须要极短的JVM GC停顿。可是，当磁盘IO压力很大时，JVM可能被阻塞一段较长的时间。

咱们对该问题进行了调查，而且发现以下缘由：

1. JVM GC须要经过发起系统调用write()，来记录GC行为。
2. write()调用能够被后台磁盘IO所阻塞。
3. 记录GC日志属于JVM停顿的一部分，所以write()调用的时间也会被计算在JVM STW的停顿时间内。

咱们提出了一系列解决该问题的方案。重要的是，咱们的发现能够帮助JVM实现来改进该问题。对于低延迟应用程序来讲，最简单有效的措施是将GC日志文件放到单独的HDD或者高性能磁盘（例如SSD）上，来避免IO竞争。

欢迎打赏（微信请点击“阅读原文”），也请关注微信公众帐号“重度恐高症”，精彩技术文章就在这里。