一个GC频繁的Case

前两天碰到一个很诡异的GC频繁的现象，走了不少弯路，N种方法查找后才终于查明原因了，在这篇blog中记录下，以便以后碰到这类问题时能更快的解决。

前两天一位同学找到我，说有个应用在启动后就一直Full GC，拿到GC log先看了下，确实是非常的诡异，截取的部分log如下：
2011-07-16T14:55:57.733+0800: 174042.063: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728400K->728457K(1048576K)] 1514832K->728457K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5426550 secs] [Times: user=4.58 sys=0.21, real=1.54 secs]
2011-07-16T14:56:07.144+0800: 174051.475: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728457K->728611K(1048576K)] 1514889K->728611K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5428850 secs] [Times: user=4.57 sys=0.17, real=1.54 secs]
2011-07-16T14:56:16.699+0800: 174061.030: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728611K->729096K(1048576K)] 1515043K->729096K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5064200 secs] [Times: user=4.36 sys=0.21, real=1.50 secs]
2011-07-16T14:56:26.420+0800: 174070.750: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729096K->729654K(1048576K)] 1515528K->729654K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5519220 secs] [Times: user=4.47 sys=0.18, real=1.54 secs]
2011-07-16T14:56:35.634+0800: 174079.965: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729654K->728743K(1048576K)] 1516086K->728743K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5002720 secs] [Times: user=4.67 sys=0.11, real=1.50 secs]
2011-07-16T14:56:45.938+0800: 174090.269: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 728743K->729132K(1048576K)] 1515175K->729132K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.6175360 secs] [Times: user=4.47 sys=0.25, real=1.61 secs]
2011-07-16T14:56:55.682+0800: 174100.012: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729132K->728950K(1048576K)] 1515564K->728950K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5780950 secs] [Times: user=4.50 sys=0.07, real=1.58 secs]
2011-07-16T14:57:05.228+0800: 174109.559: [Full GC [PSYoungGen: 786408K->0K(917504K)] [ParOldGen: 728950K->729466K(1048576K)] 1515359K->729466K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 1.5868130 secs] [Times: user=4.43 sys=0.09, real=1.60 secs]
2011-07-16T14:57:14.812+0800: 174119.142: [Full GC [PSYoungGen: 786432K->0K(917504K)] [ParOldGen: 729466K->729277K(1048576K)] 1515898K->729277K(1966080K) [PSPermGen: 84814K->84812K(262144K)], 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’后，看到了一些信息：
11284-#8 0x000000329b8d3c2d in clone () from /lib64/libc.so.6
11341-Thread 259 (Thread 0x40b25940 (LWP 20346)):
11385-#0 0x000000329c40ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
11445-#1 0x00002b57b7843727 in os::PlatformEvent::park ()
11498-#2 0x00002b57b781c7c2 in Monitor::IWait ()
11542-#3 0x00002b57b781cf8e in Monitor::wait ()
11585-#4 0x00002b57b75e6aa2 in WaitForBarrierGCTask::wait_for ()
11645-#5 0x00002b57b7887d8b in PSParallelCompact::marking_phase ()
11707-#6 0x00002b57b7886e11 in PSParallelCompact::invoke_no_policy ()
11772-#7 0x00002b57b788d296 in PSScavenge::invoke ()
11820:#8 0x00002b57b7855d7e in ParallelScavengeHeap::failed_mem_allocate ()
11891-#9 0x00002b57b796b379 in VM_ParallelGCFailedAllocation::doit ()
11956-#10 0x00002b57b7977d0a in VM_Operation::evaluate ()
12008-#11 0x00002b57b79772b2 in VMThread::evaluate_operation ()
12066-#12 0x00002b57b7977534 in VMThread::loop ()
12110-#13 0x00002b57b797702e in VMThread::run ()
12153-#14 0x00002b57b7843f9f in java_start ()
12193-#15 0x000000329c4064a7 in start_thread () from /lib64/libpthread.so.0
12263-#16 0x000000329b8d3c2d in clone () from /lib64/libc.so.6
12320-Thread 258 (Thread 0x40ba6940 (LWP 20347)):
12364-#0 0x000000329c40ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
–
69798-#3 0x00002b57b78f56c3 in ObjectSynchronizer::wait ()
69852-#4 0x00002b57b76bd34b in JVM_MonitorWait ()
69897-#5 0x00002aaaab141ece in ?? ()
69929-#6 0×0000000000000000 in ?? ()
69961-Thread 141 (Thread 0x45f27940 (LWP 20532)):
70005-#0 0x000000329c40ab99 in pthread_cond_wait@@GLIBC_2.3.2 ()
70065-#1 0x00002b57b7843727 in os::PlatformEvent::park ()
70118-#2 0x00002b57b781c7c2 in Monitor::IWait ()
70162-#3 0x00002b57b781ce2a in Monitor::wait ()
70205-#4 0x00002b57b7977b39 in VMThread::execute ()
70252:#5 0x00002b57b7855c0b in ParallelScavengeHeap::mem_allocate ()
70316:#6 0x00002b57b747873b in CollectedHeap::common_mem_allocate_noinit ()
70387-#7 0x00002b57b7626ce2 in instanceKlass::allocate_instance ()
70449-#8 0x00002b57b78aa076 in OptoRuntime::new_instance_C ()
70506-#9 0x00002aaaab1948fb in ?? ()
70538-#10 0x00002aaac0741768 in ?? ()
70570-#11 0x00002aaaab761a0c in ?? ()
70602-#12 0x00002aab2dae03c8 in ?? ()
70634-#13 0x00002aaac4035fb0 in ?? ()
70666-#14 0x00002aab2dae2c00 in ?? ()
70698-#15 0x00002aaac0218af0 in ?? ()
70730-#16 0×0000000000000001 in ?? ()
拿到这个堆栈后，猜测是由于该线程在分配一个对象时分配失败，导致触发了Full GC，于是根据线程ID去找jstack中的信息，很杯具的是由于有时间差，每次都抓不到什么信息。

于是仔细的重新看上面的堆栈，发现在ParallelScavengeHeap::mem_allocate后，进入了VMThread::execute，根据ParallelScavengeHeap的代码：
[code]
// Generate a VM operation
VM_ParallelGCFailedAllocation op(size, is_tlab, gc_count);
VMThread::execute(&op);
[/code]
在分配失败时，会通过VMThread来执行failed_mem_allocate，这和堆栈信息也对应上了，于是继续看上面的堆栈信息，最关键的是这几段：
11707-#6 0x00002b57b7886e11 in PSParallelCompact::invoke_no_policy ()
11772-#7 0x00002b57b788d296 in PSScavenge::invoke ()
11820:#8 0x00002b57b7855d7e in ParallelScavengeHeap::failed_mem_allocate ()
11891-#9 0x00002b57b796b379 in VM_ParallelGCFailedAllocation::doit ()
根据这个堆栈来看，ParallelScavengeHeap::failed_mem_allocate调到了PSScavenge::invoke()，这个动作是用于执行新生代回收的，但诡异的是这个堆栈上PSScavenge::invoke后，竟然进入了PSParallelCompact代码，也就是Full GC，这也就说明并不是应用分配了一个巨大的对象，而是正常的Young GC的触发（其实这个从jstat中就证明了，只是当时太不细心了），到这一步了，那么关键的问题就是为什么在触发YGC的时候，变成了直接触发Full GC，从代码上来看如下：
[code]
bool scavenge_was_done = PSScavenge::invoke_no_policy();

PSGCAdaptivePolicyCounters* counters = heap->gc_policy_counters();
if (UsePerfData)
counters->update_full_follows_scavenge(0);
if (!scavenge_was_done ||
policy->should_full_GC(heap->old_gen()->free_in_bytes())) {
if (UsePerfData)
counters->update_full_follows_scavenge(full_follows_scavenge);

GCCauseSetter gccs(heap, GCCause::_adaptive_size_policy);
if (UseParallelOldGC) {
PSParallelCompact::invoke_no_policy(false);
} else {
PSMarkSweep::invoke_no_policy(false);
}
}
[/code]
从上面代码来看，只有scavenge_was_done为false或policy->should_full_GC(heap->old_gen()->free_in_bytes())为true时，才会触发PSParallelCompact，而从GC日志来看，是没有触发YGC的，于是继续看PSScavenge::invoke_no_policy代码，从代码来看，只有在下面的代码已经返回的情况下，才会没有任何YGC的日志信息：
[code]
// Check for potential problems.
if (!should_attempt_scavenge()) {
return false;
}
[/code]
而should_attempt_scavenge这段代码中最关键的部分如下：
[code]
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();
[/code]
这也就是常说的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=1073741824
sun.gc.generation.1.space.0.initCapacity=1073741824
sun.gc.generation.1.space.0.maxCapacity=1073741824
sun.gc.generation.1.space.0.name=”old”
sun.gc.generation.1.space.0.used=744389904

sun.gc.policy.avgBaseFootprint=355284672
sun.gc.policy.avgMajorIntervalTime=9105
sun.gc.policy.avgMajorPauseTime=1640
sun.gc.policy.avgMinorIntervalTime=5171
sun.gc.policy.avgMinorPauseTime=330
sun.gc.policy.avgOldLive=744361216
sun.gc.policy.avgPretenuredPaddedAvg=251
sun.gc.policy.avgPromotedAvg=178848128
sun.gc.policy.avgPromotedDev=106732344
sun.gc.policy.avgPromotedPaddedAvg=499045152
悲观策略检查的其实就是avgPromotedPaddedAvg < space.0.capacity - space.0.used。
于是原因终于清楚了，由于平均晋升的大小一直 > 旧生代的剩余空间（因为每次FGC后旧生代都只有300多M是空余的，这个在这个应用中是正常的），导致每次YGC的时候悲观策略一直触发，于是看到的就是频繁Full GC了，在这个应用中的解决方法比较简单，就是把旧生代放大一点，避免这个现象，例如：-Xms3g -Xmx3g。

可能有同学要关心为什么平均晋升大小会那么大，重启了个别机器，看到刚重启时的gc log如下：
2011-07-17T10:59:03.481+0800: 10.160: [GC [PSYoungGen: 786432K->23851K(917504K)] 786432K->23851K(3014656K), 0.0967130 secs] [Times: user=0.08 sys=0.03, real=0.09 secs]
2011-07-17T10:59:12.633+0800: 19.312: [GC [PSYoungGen: 810283K->64502K(917504K)] 810283K->64502K(3014656K), 0.0728670 secs] [Times: user=0.17 sys=0.06, real=0.07 secs]
2011-07-17T10:59:16.286+0800: 22.965: [GC [PSYoungGen: 850934K->131064K(917504K)] 850934K->284737K(3014656K), 0.3072120 secs] [Times: user=0.91 sys=0.29, real=0.31 secs]
2011-07-17T10:59:19.405+0800: 26.084: [GC [PSYoungGen: 917496K->131047K(917504K)] 1071169K->606647K(3014656K), 0.5184690 secs] [Times: user=1.73 sys=0.32, real=0.52 secs]
2011-07-17T10:59:21.590+0800: 28.268: [GC [PSYoungGen: 917479K->131048K(917504K)] 1393079K->1019546K(3014656K), 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留有一定的空间，否则悲观策略就要发威了，:)。