java gc 时间长_如何避免后台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: 31205