原文：Eliminating Large JVM GC Pauses Caused by Background IO Traffic
在生产环境中，我们屡次看到在JVM（Java虚拟机）中运行的应用程序偶尔会遭遇比较严重的暂停，我们称之为STW（Stop－The－World），这个现象是因为JVM的GC日志记录进程被后台IO阻塞（比如系统页缓存的回写）锁定所引起的。在STW暂停期间，JVM暂停了所有的应用线程，应用程序停止响应用户的请求，因此对于一些等待敏感的用户操作，这种暂停会造成不可接受的延迟。
我们的调查显示，暂停是由于JVM GC（垃圾回收）在GC日志记录过程中的write()系统调用诱导引起的。这类写日志的操作，即便是采用了异步写模式（比如缓冲IO或者非阻塞IO），仍然会被操作系统的机制包括页缓存写会锁定相当长的时间。
我们讨论了多种方案来缓解该问题。对于延迟敏感的Java应用，我们建议将Java日志文件已到一个独立的或高性能的磁盘上（如SSD，tmpfs等）。
生产问题
当JVM管理的堆空间进行了垃圾回收，JVM可能会停止，从而导致了应用的STW暂停。鉴于启动Java实例时配置的选项不同，不同类型的GC和JVM活动会被记录到GC日志文件中。
尽管一些GC导致的STW暂停比如扫描、标志、整理堆对象是我们众所周知的，但是我们发现依然有很多大型的STW暂停是有后台IO阻塞引起。在我们的生产环境中，我们看到了在关键任务的Java应用中很多无法解释的大型STW暂停（>5s）。这样的暂停不能被应用层面的逻辑和JVM GC活动所解释。如下面所示，展现了一个大型的超过4s的STW暂停和一些GC信息。垃圾收集器是G1。G1具有一个8GB的堆空间和并行的新生代垃圾收集，一般来讲整个垃圾回收过程仅需小于1s即可完成，简单的GC选项使开销较小。然而，应用线程竟然暂停了超过4s。GC（如回收堆空间）的工作量不足以解释4.17s这样巨大的暂停时间。
``` 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，17s的GC STW暂停
另一个例子，下面的GC日志快照展示了一个11.45s的STW暂停。垃圾收集器是CMS（Concurrent Mode Sweep）。"用户"/"系统"时间可以忽略不计，然而"real"GC时间大于11s。最后一行明确了11.45s的应用暂停时间。
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.45sGC STW暂停
由于应用是十分延迟敏感的，我们花费了相当大的努力来研究这个问题。最终，我们重现了问题，找到了关键诱因，然后提出了几项解决方案来解决它。
在实验室环境中重现问题
首先，我们先从在实验室环境中重现这个无法解释的大型JVM暂停开始。出于可控性和重复性的考虑，我们设计了一个简单的工作负载来移除生产应用程序的复杂性。
我们在两个场景中运行这个工作负载：具备和不具备后台IO活动。不具备后台IO的场景用作“基线”，另一个引入后台IO的场景用于重现问题。
Java工作负载
我们所使用的Java工作负载用向队列中持续分配10KB的对象。当对象数量达到100，000时，一半的对象会被移除队列。所以堆中对象的最大值时100，000个对象，约占用原始大小10GB。进程会持续固定的一段时间（如5min）。
Java源码和生成后台IO的脚本，都开源在这里
https://github.com/zhenyun/JavaGCworkload。我们考虑的主要性能指标是大JVM GC暂停的次数。
后台IO
后台IO是由脚本引入，该脚本负责持续的复制大文件。后台工作负载大约产生150MB/s的写负载，足以使单个硬盘跑满。为了看到产生的IO负载有多严重，我们使用"sar －d －p 2"来收集一下统计数据：await（设备发出的IO请求送达的平均时间（单位，毫秒）），tps（每秒传输到物理设备上的数量总和）和wrsec-per-s（写入到设备的扇区数）。平均数值是：await＝421ms，tps＝305，wrsec-per-s=302K。
系统配置
场景1（无后台IO负载）
作为基线，本次运行无后台IO负载。所有JVM GC暂停的时间序列数据所示如下图所示。没有发现超过250ms的单一暂停。
场景一中的所有JVM GC暂停（无后台IO负载）
场景2（有后台IO负载）
当后台IO运行时，同样的Java工作负载在5分钟的运行期间，能够看到3.6s的STW暂停，和三个超过0.5s的暂停。
场景二中的所有JVM GC暂停（有后台IO负载）
调查
为了弄明白是什么系统调用引起的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> 捕获的JVM打开GC日志文件产生的open()系统调用
然而，快照显示由JVM调用的异步write()系统调用有不同寻常的较长的执行时间。检查系统调用和JVM暂停的时间戳，我们发现他们具备强烈的关联关系。在下面的两张图表，我们展示了2分钟内的延迟情况。
时间序列相关（JVM STW暂停）。
时间序列相关（write()系统调用延迟）
接着，我们放大焦点，关注发生在13:32:35时最大1.59s暂停。下面展示了相关的GC日志和strace输出：
GC日志和strace输出
让我们来尝试理解究竟发生了什么：
1、35.04时（第2行），新生代GC启动，花费0.12s完成
2、新生代GC在35.17完成，JVM进行系统调用write()，尝试将新生代GC统计输出到GC日志文件（第4行）
3、write()调用被锁定1.47s，最终在36.64（第5行）完成，花费1.47s。
4、当write()调用在36.64返回JVM，JVM纪录了1.59s的STW暂停（0.12+1.47）（第3行）
换句话说，实际的STW暂停由两部分组成：（1）GC时间（本例中新生代GC所花费时间）；（2）GC日记录日志所花费的时间（本例中的write()时间）。
这些数据表明，GC日志记录过程算在了JVM STW暂停中，日志记录的时间被当作STW暂停的一部分。特别的，整个应用的暂停主要包含两部分：因为JVM GC活动引起的暂停和因为在JVM GC日志记录时由操作系统阻塞write()系统调用所产生的暂停。下面的图表展示了两者的关系。
日志记录期间JVM和操作系统的相互作用
如果GC日志记录被操作系统阻塞，阻塞的时间也被计算为STW暂停的一部分。然而新问题是，为何缓冲写会被阻塞？翻阅大量的资源包括内核源码，我们意识到缓冲写可能卡在内核代码。包括多个原因，如：（1）稳定页写操作；（2）日志提交。
稳定页写操作：JVM向GC日志文件中的写操作首先修改了相关的文件缓存页内容。即使缓存页稍后会通过操作系统的写回机制持久化到磁盘文件中，对内存中页的修改仍然会造成由“稳定页写操作”引起的页面争用。在“稳定页写操作”时，如果页面正在被操作系统写回，对这个页的write()操作必须等待写回完成。页面锁定来确保数据的一致性，避免部分新的一页保留到磁盘。
日志提交：对于日志文件系统，适当的日志在文件写入期间生成。写入新内容到GC日志文件导致新的块被分配，文件系统需要先将日志数据提交到文件。在日志提交期间，如果操作系统具有其他IO活动，提交操作可能需要稍作等待。如果后台IO活动比较繁重，则等待时间会明显加长。值得注意的是，EXT4文件系统具备一项“延迟分配”的特性，来推迟某些特定日志数据的操作系统写回时间，可以有效缓解这个问题。此外要注意的是，将EXT4的数据模式从默认的“有序”更改为“写回”并不会真正处理这个问题，因为日志需要在写扩展调用返回前就被持久化。
后台IO活动
从特定的JVM垃圾收集的角度来说，在典型的生产环境中，后台IO活动是不可避免的。有几类产生IO活动的源头：（1）系统活动；（2）管理软件；（3）其他协同应用；（4）同一JVM实例产生的IO。首先，操作系统包含许多机制（比如“／proc”文件系统）将数据写入底层磁盘。第二，系统级的软件比如CFEngine也会产生磁盘IO。第三，如果节点需要和其他应用协同共享磁盘，则其他应用会竞争IO。第四，特定的JVM实例也可能产生除GC日志之外的磁盘IO。
解决方案
尽管在当前的HotSpot JVM实现（也存在于其他虚拟机）中，GC日志记录过程会被后台IO活动阻塞，我们仍然有很多解决方案来帮助在写入到GC日志文件时缓解这个问题。
首先，增强JVM可以完全的解决这个问题。尤其，当GC日志记录活动和引起STW暂停的JVM GC进程分裂，这个问题就会消失不见。举例来说，JVM可以将GC日志记录功能，放入一个不同的线程来单独处理日志文件写操作，因此，不会造成STW暂停。但是独立线程来记录日志会存在JVM崩溃时丢失GC日志信息的风险。暴露给用户一个JVM标志位允许用户指定偏好应当时不错的选择。
由于后台IO引起的STW暂停时间的长短依赖于究竟IO负载有多繁重，那么我们可以采用各种方式来减少后台IO的强烈程度。举例来说，在同一个节点上取消已分配的其他IO密集型应用程序，减少其它类型的日志记录，改进日志循环等。
对于延迟敏感的应用来讲，比如服务用户进行交互操作，稍微大的STW暂停（比如大于0.25s）都是不可容忍的。因此，需要实施特别的方案。确保没有由系统诱导产生的较大STW暂停的最底线就是使GC日志记录动作避免被操作系统IO活动阻塞。
一种解决方案是将GC日志放入tmpfs（比如，-Xloggc:/tmpfs/gc.log）。因为tmpfs没有磁盘备份，写入到tmpfs不会产生磁盘活动，因此也不会被磁盘IO阻塞。但是这种方式存在两个问题：（1）GC日志文件会在系统宕机时丢失；（2）tmpfs消耗物理内存。一种缓解方案就是隔段时间将日志文件持久化备份，可以减少丢失的数量。
另一种方案就是将GC日志文件放置在SSD（Solid－State Drives，固态硬盘）上，固态硬盘具备更好的IO性能。根据IO负载，SSD可用作GC日志记录专属的驱动器，或者与其他IO负载应用共享。然而，SSD的价格需要考虑在成本中。
相较使用SSD，一个更具成本效益的优胜方案是将GC日志文件放入一个专用的硬盘上面。由于该硬盘仅提供GC日志记录，所以产生的磁盘IO看起来能达到降低暂停，提高JVM性能的目标。事实上，上面我们展示的场景1中，就用了这种配置方式，因此采用这种方式可以保证在GC日志记录驱动器上没有其它IO活动存在。
评估将GC日志放置在SSD和tmpfs上
我们采用了专有文件系统的方式，将GC日志放置在SSD和tmpfs驱动器上。我们运行了和场景2中同样的Java负载和后台IO负载。
对于SSD和tmpfs，我们观察到了相似的结果，下面的图表展示了将GC日志文件放置在SSD磁盘上的结果。我们发现JVM暂停性能比场景1中略差，但是所有的暂停均小于0.25s。结果表明，后台IO负载并没有影响应用的性能。
将GC日志记录到SSD上所有的JVM STW暂停
结论
延迟敏感的Java应用程序需要较小的JVM GC暂停。然而，当磁盘IO繁重时，JVM明显会被阻塞一段时间。
我们研究了这个问题，并且得出以下结论：
1、JVM GC需要write()系统调用来记录GC活动；
2、由于后台磁盘IO，像write()这样的调用会被阻塞；
3、GC日志记录过程是JVM暂停的一部分，因此write()调用的时间会计算在JVM STW暂停时间中。
我们提出了一系列的解决方案来缓解这个问题。尤其的，调查结果可以用于提高 JVM 实现，以避免此问题。对于延迟敏感的应用程序，一个即刻生效的解决方案即是将GC日志文件放置在单独的硬盘或者高性能的磁盘驱动器，如SSD上面，来避免IO竞争。
