CrashReport系统在游戏内测当天出现了异常情况JVM僵死,通过top -p <PID> -H 结合jstack(jstack -m -l pid)查看,发现是VM Thread线程CPU占用100%,线程ID好为18540,线程信息如下:
----------------- 18540 -----------------
0xb7904280 _ZN9MarkSweep12follow_stackEv + 0x30
0xb79b0637 _ZN11PSMarkSweep17mark_sweep_phase1Eb + 0xe7
0xb79af737 _ZN11PSMarkSweep16invoke_no_policyEb + 0x3c7
0xb79ba0ae _ZN10PSScavenge6invokeEv + 0x12e
0xb797f999 _ZN20ParallelScavengeHeap19failed_mem_allocateEjb + 0x49
0xb7ab191a _ZN29VM_ParallelGCFailedAllocation4doitEv + 0x5a
0xb7ac0096 _ZN12VM_Operation8evaluateEv + 0x46
0xb7abf523 _ZN8VMThread18evaluate_operationEP12VM_Operation + 0x83
0xb7abf794 _ZN8VMThread4loopEv + 0x194
0xb7abf280 _ZN8VMThread3runEv + 0x80
0xb796d64e _Z10java_startP6Thread + 0x14e
0x0056849b start_thread + 0xcb
Parallel GC 是JVM的垃圾回收线程( ParallelGC垃圾回收方式的特点是在New区开启多线程回收)
既然是垃圾回收线程CPU占用100%,那么说明我们的应用的JVM内存使用有问题,借助jstat查看JVM的内存信息如下:
jstat -gcutil pid 5000 #这里是说每隔5000毫秒打印异常JVM内存信息
存活区0
存活区1
伊甸区
Old区
永久区
新生带GC次数
新生带GC时间
Full GC次数
Full GC时间
GC的总时间
S0
S1
E
O
P
YGC
YGCT
FGC
FGCT
GCT
0.00
100
98.75
584
13.28
1447
3699.659
3712.939
1448
3702.135
3715.416
存活区0和存活区1的内存占用都是0%,伊甸区使用100%,Old区使用也是100%,Full GC的次数达到1448(3个小时内,差不多9s做一次Full GC,每次Full GC花费2.56s)
也就是说我们的应用频繁的在做Full GC,而且Full GC消耗的时间也比较长,应用在做Full GC是整个应用是会阻塞的,所以在这种情况下我们的应用几乎是不可用的。
什么情况下会引发Full GC呢?参考下图:
Old区内存不够是JVM会触发Full GC,由于Old区一直是满的,所以会频繁触发Full GC,但是这个频度也不高,应该不至于导致CPU使用100%,我们用的是Parallel GC(并行GC),并行GC是说在新生带会采取多线程来进行垃圾回收,由于我们Eden区也是满的,所以GC的线程会CPU占用100%。
怎么查看我们的JVM每个区的内存大小情况呢?用jstat -gccapacity <PID>可以得到结果如下:
新生带最小
新生带最大
新生带当前
存活区
老年带最小
老年带最大
老年带当前
Old区内存占用
永久区最小
永久区最大
永久区当前
永久区内存占用
Full GC 次数
NGCMN
NGCMX
NGC
S0C
S1C
EC
OGCMN
OGCMX
OGC
OC
PGCMN
PGCMX
PGC
PC
21824
349504
64384
2112
3904
56448
43712
699072
178496
16384
65536
35712
146
9
21.3125
341.3125
62.875
2.0625
3.8125
55.125
42.6875
682.6875
174.3125
16
64
34.875
我们的Eden区较小,这个可能会触发JVM的一个BUG(1.6u18前的版本,我们的版本是:java version "1.6.0_37")正好在这个范围内,具体信息查看:http://www.oschina.net/question/1092_24066
尝试升级jdk版本或者调整JVM内存参数解决该问题。