内存溢出异常处理

参考文档: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]

结合Dump分析:

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 159,569评论 4 363
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 67,499评论 1 294
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 109,271评论 0 244
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 44,087评论 0 209
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 52,474评论 3 287
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 40,670评论 1 222
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,911评论 2 313
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 30,636评论 0 202
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 34,397评论 1 246
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 30,607评论 2 246
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 32,093评论 1 261
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 28,418评论 2 254
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 33,074评论 3 237
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 26,092评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,865评论 0 196
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 35,726评论 2 276
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 35,627评论 2 270

推荐阅读更多精彩内容