频繁gc是什么意思_[转]一个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的代码:

1

2

3

//

Generate a VM operation

VM_ParallelGCFailedAllocation op(size, is_tlab,

gc_count);

VMThread::execute(&op);

在分配失败时,会通过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,从代码上来看如下:

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

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留有一定的空间,否则悲观策略就要发威了,:)。

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值