内存溢出异常处理
参考文档:Java Collectors
[GC [< collector >: < starting occupancy1 > -> < ending occupancy1 >, < pause time1 > secs] < starting occupancy3 > -> < ending occupancy3 >, < pause time3 > secs]
< collector > GC收集器的名称
< starting occupancy1 > 新生代在GC前占用的内存
< ending occupancy1 > 新生代在GC后占用的内存
< pause time1 > 新生代局部收集时jvm暂停处理的时间
< starting occupancy3 > JVM Heap 在GC前占用的内存
< ending occupancy3 > JVM Heap 在GC后占用的内存
< pause time3 > GC过程中jvm暂停处理的总时间
执行参数:
-Xms128M -Xmx256M -XX:PermSize=64M -XX:MaxPermSize=64M -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled -XX:+ParallelRefProcEnabled -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingOccupancyFraction=80 -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSFullGCsBeforeCompaction=5 -XX+UseCMSCompactAtFullCollection -XX:+PrintGCDetails -XX:+HeapDumpOnOutOfMemoryError
所以:
PermSize=67108864(非堆内存大小,Perm代大小)
InitialHeapSize=134217728(初始化堆内存大小)
MaxHeapSize=268435456 (最大堆内存大小)
NewSize=89481216(Young代内存大小)
MaxNewSize=89481216(Young代内存最大大小)
OldSize=178954240(Old代内存大小)
正常的CMS处理流程:
2017-03-15T19:00:24.845+0800: 9.826: [GC [1 CMS-initial-mark: 36126K(43712K)] 44831K(122368K), 0.0220800 secs] [Times: user=0.05 sys=0.02, real=0.02 secs]
2017-03-15T19:00:24.868+0800: 9.848: [CMS-concurrent-mark-start]
2017-03-15T19:00:25.130+0800: 10.110: [CMS-concurrent-mark: 0.256/0.262 secs] [Times: user=0.45 sys=0.14, real=0.26 secs]
2017-03-15T19:00:25.130+0800: 10.110: [CMS-concurrent-preclean-start]
2017-03-15T19:00:25.130+0800: 10.111: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
2017-03-15T19:00:25.131+0800: 10.111: [CMS-concurrent-abortable-preclean-start]
2017-03-15T19:00:25.475+0800: 10.455: [GC2017-03-15T19:00:25.475+0800: 10.455: [ParNew: 78656K->8704K(78656K), 0.1270550 secs] 114782K->47719K(122368K), 0.1272540 secs] [Times: user=0.29 sys=0.02, real=0.12 secs]
2017-03-15T19:00:25.898+0800: 10.878: [CMS-concurrent-abortable-preclean: 0.270/0.767 secs] [Times: user=2.42 sys=0.06, real=0.77 secs]
2017-03-15T19:00:25.904+0800: 10.884: [GC[YG occupancy: 63473 K (78656 K)]2017-03-15T19:00:25.904+0800: 10.884: [Rescan (parallel) , 0.0750590 secs]2017-03-15T19:00:25.979+0800: 10.960: [weak refs processing, 0.0104990 secs]2017-03-15T19:00:25.990+0800: 10.970: [class unloading, 0.0014200 secs]2017-03-15T19:00:25.991+0800: 10.972: [scrub symbol table, 0.0028960 secs]2017-03-15T19:00:25.994+0800: 10.975: [scrub string table, 0.0006860 secs] [1 CMS-remark: 39015K(43712K)] 102488K(122368K), 0.0912600 secs] [Times: user=0.34 sys=0.00, real=0.09 secs]
2017-03-15T19:00:25.999+0800: 10.979: [CMS-concurrent-sweep-start]
2017-03-15T19:00:26.024+0800: 11.004: [CMS-concurrent-sweep: 0.024/0.025 secs] [Times: user=0.09 sys=0.00, real=0.03 secs]
2017-03-15T19:00:26.024+0800: 11.004: [CMS-concurrent-reset-start]
2017-03-15T19:00:26.027+0800: 11.007: [CMS-concurrent-reset: 0.003/0.003 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
说明:
【初始化记录,会停顿】[GC [1 CMS-initial-mark: 当前old代大小 (old代容量) ] 当前堆内大小 (堆容量)
【标记开始】
【标记结束及耗时】
【预清理开始】
【预清理结束】
【可中断预清理开始】
【执行了ParNew GC】[ParNew: 当前Young代大小->回收后Young代大小(Young代容量), 0.1270550 secs] 回收前堆的大小->回收后堆的大小(堆的容量)
【可中断预清理结束】
【CMS处理过程,在remark时会停顿】
【清理开始】
【清理结束】
【重置开始】
【重置结束】
恶化流程分析:
查询整个GC Log,找到恶化衔接点:
2017-03-16T13:19:17.213+0800: 65942.193: [GC2017-03-16T13:19:17.214+0800: 65942.194: [ParNew: 78656K->78656K(78656K), 0.0000890 secs]2017-03-16T13:19:17.214+0800: 65942.194: [CMS: 171692K->174783K(174784K), 1.0692500 secs] 250348K->179670K(253440K), [CMS Perm : 55543K->55525K(65536K)], 1.0706310 secs] [Times: user=12.60 sys=0.00, real=1.07 secs] 【想要通过GC,腾空Young,但是明显Old也不够地方了,要开始对Old做CMS】
2017-03-16T13:19:18.287+0800: 65943.267: [GC [1 CMS-initial-mark: 174783K(174784K)] 179700K(253440K), 0.0125980 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
···
2017-03-16T13:19:19.074+0800: 65944.055: [GC[YG occupancy: 5318 K (78656 K)]2017-03-16T13:19:19.075+0800: 65944.055: [Rescan (parallel) , 0.0074880 secs]2017-03-16T13:19:19.082+0800: 65944.062: [weak refs processing, 0.0027200 secs]2017-03-16T13:19:19.085+0800: 65944.065: [class unloading, 0.0067020 secs]2017-03-16T13:19:19.092+0800: 65944.072: [scrub symbol table, 0.0140110 secs]2017-03-16T13:19:19.106+0800: 65944.086: [scrub string table, 0.0014150 secs] [1 CMS-remark: 174783K(174784K)] 180102K(253440K), 0.0345230 secs] [Times: user=0.00 sys=0.00, real=0.03 secs]
···
2017-03-16T13:19:19.247+0800: 65944.227: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
至
2017-03-16T14:30:00.068+0800: 70185.049: [GC [1 CMS-initial-mark: 174553K(174784K)] 253175K(253440K), 0.1776490 secs] [Times: user=0.18 sys=0.00, real=0.18 secs]
2017-03-16T14:30:00.248+0800: 70185.228: [CMS-concurrent-mark-start]
2017-03-16T14:30:00.249+0800: 70185.229: [GC2017-03-16T14:30:00.250+0800: 70185.230: [ParNew: 78656K->78656K(78656K), 0.0000570 secs]2017-03-16T14:30:00.250+0800: 70185.230: [CMS2017-03-16T14:30:00.623+0800: 70185.604: [CMS-concurrent-mark: 0.364/0.375 secs] [Times: user=0.38 sys=0.00, real=0.38 secs]
(concurrent mode failure): 174553K->174784K(174784K), 1.6327610 secs] 253209K->185593K(253440K), [CMS Perm : 55528K->55525K(65536K)], 1.6338660 secs] [Times: user=1.62 sys=0.00, real=1.64 secs] 【concurrent mode failure,CMS回收Old代速度太慢了,CMS工作完成前Old已经被填满了,需要降低CMSInitiatingOccupancyFraction】
2017-03-16T14:30:02.137+0800: 70187.117: [GC [1 CMS-initial-mark: 174784K(174784K)] 202184K(253440K), 0.0560980 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
···
2017-03-16T14:30:02.944+0800: 70187.925: [GC[YG occupancy: 29953 K (78656 K)]2017-03-16T14:30:02.945+0800: 70187.925: [Rescan (parallel) , 0.0363880 secs]2017-03-16T14:30:02.981+0800: 70187.961: [weak refs processing, 0.0018180 secs]2017-03-16T14:30:02.983+0800: 70187.963: [class unloading, 0.0068980 secs]2017-03-16T14:30:02.990+0800: 70187.970: [scrub symbol table, 0.0135000 secs]2017-03-16T14:30:03.003+0800: 70187.984: [scrub string table, 0.0014260 secs] [1 CMS-remark: 174784K(174784K)] 204737K(253440K), 0.0619150 secs] [Times: user=0.17 sys=0.00, real=0.06 secs]
···
2017-03-16T14:30:03.153+0800: 70188.133: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]