当前位置: 首页 > Java > 正文

某应用GC频繁的问题

1 星2 星3 星4 星5 星 (暂无评分)
Loading ... Loading ...
baidu_share

错误日志如下:

1
2
3
4
5
6
7
8
9
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的时候旧生代都还有很多的空间,于是去看来下启动参数,此时的启动参数如下:

1
-Xmx2048m -Xms2048m -Xmn1024m -Xss512k -XX:PermSize=256m -XX:+UseParallelGC -XX:ParallelGCThreads=20 -XX:+UseParallelOldGC -XX:MaxGCPauseMillis=100 -XX:+UseAdaptiveSizePolicy -XX:+DisableExplicitGC

可以看到,这个启动参数有很多的问题,最重要的在于MaxGCPauseMillis,因为目前版本的jdk其实很难做到达成这个目标,于是猜测可能是这个参数造成的,顺带把启动参数简单修改了下:

1
-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’后,看到了一些信息:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
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的代码:

1
2
3
// Generate a VM operation
VM_ParallelGCFailedAllocation op(size, is_tlab, gc_count);
VMThread::execute(&op);

在分配失败时,会通过VMThread来执行failed_mem_allocate,这和堆栈信息也对应上了,于是继续看上面的堆栈信息,最关键的是这几段:

1
2
3
4
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,从代码上来看如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
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);
  }
}

从上面代码来看,只有scavenge_was_done为false或policy->should_full_GC(heap->old_gen()->free_in_bytes())为true时,才会触发PSParallelCompact,而从GC日志来看,是没有触发YGC的,于是继续看PSScavenge::invoke_no_policy代码,从代码来看,只有在下面的代码已经返回的情况下,才会没有任何YGC的日志信息:

1
2
3
4
// Check for potential problems.
if (!should_attempt_scavenge()) {
  return false;
}

而should_attempt_scavenge这段代码中最关键的部分如下:

1
2
3
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来看看到底怎么样,于是,执行了:

1
jstat -J-Djstat.showUnsupported=true -snap [pid]

截取部分最重要的信息如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
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如下:

1
2
3
4
5
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留有一定的空间,否则悲观策略就要发威了.

本文固定链接: http://www.chepoo.com/application-often-gc-error.html | IT技术精华网

某应用GC频繁的问题:等您坐沙发呢!

发表评论