[转]一个GC频繁的Case
前两天碰到一个很诡异的GC频繁的现象，走了不少弯路，N种方法查找后才终于查明原因了，在这篇blog中记录下，以便以后碰到这类问题时能更快的解决。
前两天一位同学找到我，说有个应用在启动后就一直Full GC，拿到GC
log先看了下，确实是非常的诡异，截取的部分log如下：
T14:55:57.733+.063: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
728400K-&48576K)]
1514832K-&66080K) [PSPermGen:
84814K-&8K)], 1.5426550 secs] [Times:
user=4.58 sys=0.21, real=1.54 secs]
T14:56:07.144+.475: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
728457K-&48576K)]
1514889K-&66080K) [PSPermGen:
84814K-&8K)], 1.5428850 secs] [Times:
user=4.57 sys=0.17, real=1.54 secs]
T14:56:16.699+.030: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
728611K-&48576K)]
1515043K-&66080K) [PSPermGen:
84814K-&8K)], 1.5064200 secs] [Times:
user=4.36 sys=0.21, real=1.50 secs]
T14:56:26.420+.750: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
729096K-&48576K)]
1515528K-&66080K) [PSPermGen:
84814K-&8K)], 1.5519220 secs] [Times:
user=4.47 sys=0.18, real=1.54 secs]
T14:56:35.634+.965: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
729654K-&48576K)]
1516086K-&66080K) [PSPermGen:
84814K-&8K)], 1.5002720 secs] [Times:
user=4.67 sys=0.11, real=1.50 secs]
T14:56:45.938+.269: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
728743K-&48576K)]
1515175K-&66080K) [PSPermGen:
84814K-&8K)], 1.6175360 secs] [Times:
user=4.47 sys=0.25, real=1.61 secs]
T14:56:55.682+.012: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
729132K-&48576K)]
1515564K-&66080K) [PSPermGen:
84814K-&8K)], 1.5780950 secs] [Times:
user=4.50 sys=0.07, real=1.58 secs]
T14:57:05.228+.559: [Full GC [PSYoungGen:
786408K-&0K(917504K)] [ParOldGen:
728950K-&48576K)]
1515359K-&66080K) [PSPermGen:
84814K-&8K)], 1.5868130 secs] [Times:
user=4.43 sys=0.09, real=1.60 secs]
T14:57:14.812+.142: [Full GC [PSYoungGen:
786432K-&0K(917504K)] [ParOldGen:
729466K-&48576K)]
1515898K-&66080K) [PSPermGen:
84814K-&8K)], 1.5460140 secs] [Times:
user=4.44 sys=0.19, real=1.54 secs]
这个日志中诡异的地方在于每次Full GC的时候旧生代都还有很多的空间，于是去看来下启动参数，此时的启动参数如下：
-Xmx2048m -Xms2048m -Xmn1024m -Xss512k -XX:PermSize=256m
-XX:+UseParallelGC -XX:ParallelGCThreads=20 -XX:+UseParallelOldGC
-XX:MaxGCPauseMillis=100 -XX:+UseAdaptiveSizePolicy
-XX:+DisableExplicitGC
可以看到，这个启动参数有很多的问题，最重要的在于MaxGCPauseMillis，因为目前版本的jdk其实很难做到达成这个目标，于是猜测可能是这个参数造成的，顺带把启动参数简单修改了下：
-Xmx2g -Xms2g -Xmn1g -Xss512k -XX:PermSize=256m
-XX:+UseParallelOldGC -XX:+DisableExplicitGC
修改完毕，重新启动了一台，发现OK了，于是认为就是这个参数造成的，可惜的是后面又重启了几次后，还是出现了GC频繁的现象。
从GC日志来看，Full
GC是在旧生代没满的情况下就频繁触发，以前有碰到过一个现象是代码中死循环，导致会GC频繁，于是先jmap -histo
[pid]看了下，char数组占用的比较多一些，但也是正常现象。
还有可能是程序中有地方在分配巨大的对象，导致新生代放不下，旧生代剩余的空间也放不下，于是想通过jstack先看看程序现在在干嘛，于是jstack了很多次程序的状况，杯具的是什么异常状况都没发现。
jstack中无法发现，于是决定通过pstack来看看c堆栈上的allocate的状况，想从此来关联到java的线程堆栈，多次执行pstack
[pid] | grep ‘allocate’后，看到了一些信息：
1xd3c2d in clone () from /lib64/libc.so.6
11341-Thread 259 (Thread 0x40b25940 (LWP 20346)):
1xab99 in pthread_cond_wait@@GLIBC_2.3.2
1x3727 in os::PlatformEvent::park ()
1xc7c2 in Monitor::IWait ()
1xcf8e in Monitor::wait ()
1xe6aa2 in WaitForBarrierGCTask::wait_for
1x7d8b in PSParallelCompact::marking_phase
1x6e11 in PSParallelCompact::invoke_no_policy
1xd296 in PSScavenge::invoke ()
ParallelScavengeHeap::failed_mem_allocate ()
1xb379 in VM_ParallelGCFailedAllocation::doit
1x7d0a in VM_Operation::evaluate ()
1x72b2 in VMThread::evaluate_operation
1x7534 in VMThread::loop ()
1x702e in VMThread::run ()
1x3f9f in java_start ()
1x64a7 in start_thread () from
/lib64/libpthread.so.0
1xd3c2d in clone () from
/lib64/libc.so.6
12320-Thread 258 (Thread 0x40ba6940 (LWP 20347)):
1xab99 in pthread_cond_wait@@GLIBC_2.3.2
6xf56c3 in ObjectSynchronizer::wait ()
6xbd34b in JVM_MonitorWait ()
6x00002aaaab141ece in ?? ()
6&0000 in ?? ()
69961-Thread 141 (Thread 0x45f27940 (LWP 20532)):
7xab99 in pthread_cond_wait@@GLIBC_2.3.2
7x3727 in os::PlatformEvent::park ()
7xc7c2 in Monitor::IWait ()
7xce2a in Monitor::wait ()
7x7b39 in VMThread::execute ()
7x5c0b in ParallelScavengeHeap::mem_allocate
CollectedHeap::common_mem_allocate_noinit ()
7x6ce2 in instanceKlass::allocate_instance
7xaa076 in OptoRuntime::new_instance_C ()
7x00002aaaab1948fb in ?? ()
7x00002aaac0741768 in ?? ()
7x00002aaaab761a0c in ?? ()
7x00002aab2dae03c8 in ?? ()
7x00002aaac4035fb0 in ?? ()
7x00002aab2dae2c00 in ?? ()
7x00002aaac0218af0 in ?? ()
7&0001 in ?? ()
拿到这个堆栈后，猜测是由于该线程在分配一个对象时分配失败，导致触发了Full
GC，于是根据线程ID去找jstack中的信息，很杯具的是由于有时间差，每次都抓不到什么信息。
于是仔细的重新看上面的堆栈，发现在ParallelScavengeHeap::mem_allocate后，进入了VMThread::execute，根据ParallelScavengeHeap的代码：
Generate a VM operation
VM_ParallelGCFailedAllocation op(size, is_tlab,
gc_count);
VMThread::execute(&op);
在分配失败时，会通过VMThread来执行failed_mem_allocate，这和堆栈信息也对应上了，于是继续看上面的堆栈信息，最关键的是这几段：
1x6e11 in PSParallelCompact::invoke_no_policy
1xd296 in PSScavenge::invoke ()
ParallelScavengeHeap::failed_mem_allocate ()
1xb379 in VM_ParallelGCFailedAllocation::doit
根据这个堆栈来看，ParallelScavengeHeap::failed_mem_allocate调到了
PSScavenge::invoke()，这个动作是用于执行新生代回收的，但诡异的是这个堆栈上PSScavenge::invoke后，竟然进入了
PSParallelCompact代码，也就是Full GC，这也就说明并不是应用分配了一个巨大的对象，而是正常的Young
GC的触发（其实这个从jstat中就证明了，只是当时太不细心了），到这一步了，那么关键的问题就是为什么在触发YGC的时候，变成了直接触发Full
GC，从代码上来看如下：
bool scavenge_was_done =
PSScavenge::invoke_no_policy();
PSGCAdaptivePolicyCounters* counters =
heap-&gc_policy_counters();
(UsePerfData)
&&counters-&update_full_follows_scavenge(0);
(!scavenge_was_done ||
&&&&policy-&should_full_GC(heap-&old_gen()-&free_in_bytes()))
(UsePerfData)
&&&&counters-&update_full_follows_scavenge(full_follows_scavenge);
&&GCCauseSetter
gccs(heap, GCCause::_adaptive_size_policy);
(UseParallelOldGC) {
&&&&PSParallelCompact::invoke_no_policy(false);
&&&&PSMarkSweep::invoke_no_policy(false);
从上面代码来看，只有scavenge_was_done为false或
policy-&should_full_GC(heap-&old_gen()-&free_in_bytes())为true时，
才会触发PSParallelCompact，而从GC日志来看，是没有触发YGC的，于是继续看
PSScavenge::invoke_no_policy代码，从代码来看，只有在下面的代码已经返回的情况下，才会没有任何YGC的日志信息：
Check for potential problems.
(!should_attempt_scavenge()) {
而should_attempt_scavenge这段代码中最关键的部分如下：
size_t avg_promoted = (size_t)
policy-&padded_average_promoted_in_bytes();
size_t promotion_estimate = MIN2(avg_promoted,
young_gen-&used_in_bytes());
bool result = promotion_estimate &
old_gen-&free_in_bytes();
这也就是常说的GC悲观策略了，也就是说旧生代剩余的空间小于了YGC平均晋升的大小，在GC频繁时，可以看到旧生代剩余还有300多M，觉得这不太可能呀，不过还是决定通过jstat来看看到底怎么样，于是，执行了：
jstat -J-Djstat.showUnsupported=true -snap [pid]
截取部分最重要的信息如下：
sun.gc.generation.1.name=”old”
sun.gc.generation.1.space.0.capacity=
sun.gc.generation.1.space.0.initCapacity=
sun.gc.generation.1.space.0.maxCapacity=
sun.gc.generation.1.space.0.name=”old”
sun.gc.generation.1.space.0.used=
sun.gc.policy.avgBaseFootprint=
sun.gc.policy.avgMajorIntervalTime=9105
sun.gc.policy.avgMajorPauseTime=1640
sun.gc.policy.avgMinorIntervalTime=5171
sun.gc.policy.avgMinorPauseTime=330
sun.gc.policy.avgOldLive=
sun.gc.policy.avgPretenuredPaddedAvg=251
sun.gc.policy.avgPromotedAvg=
sun.gc.policy.avgPromotedDev=
sun.gc.policy.avgPromotedPaddedAvg=
悲观策略检查的其实就是avgPromotedPaddedAvg & space.0.capacity -
space.0.used。
于是原因终于清楚了，由于平均晋升的大小一直 &
旧生代的剩余空间（因为每次FGC后旧生代都只有300多M是空余的，这个在这个应用中是正常的），导致每次YGC的时候悲观策略一直触发，于是看到的就
是频繁Full GC了，在这个应用中的解决方法比较简单，就是把旧生代放大一点，避免这个现象，例如：-Xms3g -Xmx3g。
可能有同学要关心为什么平均晋升大小会那么大，重启了个别机器，看到刚重启时的gc log如下：
T10:59:03.481+: [GC [PSYoungGen:
786432K-&2K)]
786432K-&26K), 0.0967130 secs] [Times:
user=0.08 sys=0.03, real=0.09 secs]
T10:59:12.633+: [GC [PSYoungGen:
810283K-&6K)]
810283K-&66K), 0.0728670 secs] [Times:
user=0.17 sys=0.06, real=0.07 secs]
T10:59:16.286+: [GC [PSYoungGen:
850934K-&7504K)]
850934K-&14656K), 0.3072120 secs] [Times:
user=0.91 sys=0.29, real=0.31 secs]
T10:59:19.405+: [GC [PSYoungGen:
917496K-&7504K)]
1071169K-&14656K), 0.5184690 secs] [Times:
user=1.73 sys=0.32, real=0.52 secs]
T10:59:21.590+: [GC [PSYoungGen:
917479K-&7504K)]
1393079K-&14656K), 0.5787500 secs]
[Times: user=1.78 sys=0.38, real=0.58 secs]
可以看到，这几次YGC后的平均晋升大小就是：310m+，因此如果此时旧生代只剩300m了，那么就会导致下一次YGC变成FGC，而如果下一次FGC
后旧生代剩余的仍然是300m，那么就开始频繁的FGC了，在这个应用中这个现象比较正常的原因是需要cache一个700多m的东西。
为什么把旧生代空间放大点就能好呢？因为在这个应用中，只是因为刚启动的时候需要加载如此大的cache，所以其实后面随着YGC的进行，这个平均晋升大小会越来越小，另外一个调整了参数的，运行了一天后，平均晋升大小的值为：
sun.gc.policy.avgPromotedPaddedAvg=403000
总结来看，这次排查过程还是绕了很多弯路，其实一开始就应该通过pstack来看，full
gc是什么地方在触发，然后反推就会更快的查出问题了。
从这个Case来看，对于需要Cache比较多内容的场景而言（尤其是启动时既要加载的），还是要给old留有一定的空间，否则悲观策略就要发威了，:)。
已投稿到：
以上网友发言只代表其个人观点，不代表新浪网的观点或立场。如何避免后台IO高负载造成的长时间JVM GC停顿 - 简书
<div class="fixed-btn note-fixed-download" data-toggle="popover" data-placement="left" data-html="true" data-trigger="hover" data-content=''>
写了12927字，被28人关注，获得了29个喜欢
如何避免后台IO高负载造成的长时间JVM GC停顿
译者著：其实本文的中心意思非常简单，没有耐心的读者建议直接拉到最后看结论部分，有兴趣的读者可以详细阅读一下。
发表于Linkedin Engineering，作者 是Linkedin的一名Staff Software Engineer，联合作者是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秒的停顿。
T16:09:04.088-: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 8258M-&6294M(10G), 0.1343256 secs]
T16:09:08.257-: 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秒的停顿。
T22:08:28.028+.604: [GC (Allocation Failure) : [ParNew Desired survivor size 1998848 bytes, new threshold 15 (max 15) - age
1678056 bytes,
1678056 total
: 508096K-&K), 0.0142796 secs] 1336653K-&90400K), 11.4521443 secs] [Times: user=0.18 sys=0.01, real=11.45 secs] T22:08:39.481+.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的生成脚本，都位于。我们考虑的主要性能指标是长时间JVM GC停顿的数量。
后台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停顿，我们使用了来分析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输出
我们来试着理解一下发生了什么。
在35.04时（第2行），一次young GC开始了，并且经过0.12秒完成。
这次young GC完成于时间35.17，并且JVM试图通过一次系统调用 write()（第4行），将young GC的统计信息输出到gc日志文件中。
write()调用被阻塞了1.47秒，最后于时间36.64（第5行）完成，花费了1.47秒的时间。
当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行为非常繁重，那么等待时间可能会非常长。注意，文件系统有一个“”功能，可以将journal数据提交延迟到OS回写后再进行，从而降低等待时间。还要注意的是，将EXT4的数据模式从默认的“ordered”改成“writeback”并不能解决这个问题，因为journal数据需要在write-to-extend调用返回之前被持久化。
后台IO行为
从JVM垃圾回收的角度来看，通常的生产环境都无法避免后台的IO行为。这些IO行为有几个来源：（1）OS活动；（2）管理和监控软件；（3）其他共存的应用程序；（4）同一个JVM实例的IO行为。首先，OS包含许多机制（例如，”/proc“文件系统）会引起向底层磁盘写入数据。其次，像这样的系统级软件也会进行磁盘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可能被阻塞一段较长的时间。
我们对该问题进行了调查，并且发现如下原因：
JVM GC需要通过发起系统调用write()，来记录GC行为。
write()调用可以被后台磁盘IO所阻塞。
记录GC日志属于JVM停顿的一部分，因此write()调用的时间也会被计算在JVM STW的停顿时间内。
我们提出了一系列解决该问题的方案。重要的是，我们的发现可以帮助JVM实现来改进该问题。对于低延迟应用程序来说，最简单有效的措施是将GC日志文件放到单独的HDD或者高性能磁盘（例如SSD）上，来避免IO竞争。
欢迎打赏（微信请点击“阅读原文”），也请关注微信公众账号“重度恐高症”，精彩技术文章就在这里。
如果觉得我的文章对您有用，请随意打赏。您的支持将鼓励我继续创作！
打开微信“扫一扫”，打开网页后点击屏幕右上角分享按钮
被以下专题收入，发现更多相似内容：
如果你是程序员，或者有一颗喜欢写程序的心，喜欢分享技术干货、项目经验、程序员日常囧事等等，欢迎投稿《程序员》专题。
专题主编：小...
· 224798人关注
玩转简书的第一步，从这个专题开始。
想上首页热门榜么？好内容想被更多人看到么？来投稿吧！如果被拒也不要灰心哦～入选文章会进一个队...
· 139949人关注
有关编程方面的资料
· 104人关注
如果觉得我的文章对您有用，请随意打赏。您的支持将鼓励我继续创作！
选择支付方式：