性能问答>求助一个偶发的cms gc问题>
3回复
9月前

求助一个偶发的cms gc问题



WechatIMG21.png
上图是JVM参数和gc日志,每天不定时会触发一到两次,看日志应该是大对象的分配导致的cms gc,但是过后dump内存并没有发现大对象,排查了好久还是定位不到原因,这种问题应该如何定位呢?有没有相关工具能监听gc事件然后dump内存?求助~~~

788 阅读
请先登录,再评论

看了日志,应该是短时间内有大量对象产生导致了连续两次cmsgc,但是目前没有很好的方法可以在cms触发前做heapdump,而且看下来cms其实暂停时间也不长;经验性的可以看看这个时间点前有什么服务请求在,一般来说那个时间跨度包含了CMS触发这个时刻的请求最可疑可以重点关注

19月前
回复 ferdi:

多谢,我把请求找出来分析一下看看

9月前回复

图片上传失败,补充:

java -server -Xms3G -Xmx3G -Xss256k -XX:+UseConcMarkSweepGC -Xmn1500m -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:/opt/log/app/gc.log -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/opt/log/app -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=2M -XX:CMSInitiatingOccupancyFraction=70 -XX:+UseCMSInitiatingOccupancyOnly -jar service-1.0.0-SNAPSHOT.jar --spring.profiles.active=prod
2021-08-05T03:51:49.473+0800: 552525.889: [GC (Allocation Failure) 2021-08-05T03:51:49.474+0800: 552525.889: [ParNew: 1309952K->58347K(1382400K), 0.0441196 secs] 2147218K->895673K(2992128K), 0.0444
171 secs] [Times: user=0.12 sys=0.00, real=0.04 secs] 
2021-08-05T03:53:47.440+0800: 552643.856: [GC (Allocation Failure) 2021-08-05T03:53:47.440+0800: 552643.856: [ParNew: 1287147K->71667K(1382400K), 0.0483617 secs] 2124473K->909164K(2992128K), 0.0487
078 secs] [Times: user=0.13 sys=0.00, real=0.05 secs] 
2021-08-05T03:55:21.136+0800: 552737.552: [GC (Allocation Failure) 2021-08-05T03:55:21.136+0800: 552737.552: [ParNew: 1300467K->65258K(1382400K), 0.3630364 secs] 2137964K->1116424K(2992128K), 0.363
3736 secs] [Times: user=1.13 sys=0.27, real=0.37 secs] 
2021-08-05T03:55:26.061+0800: 552742.477: [GC (Allocation Failure) 2021-08-05T03:55:26.061+0800: 552742.477: [ParNew: 174475K->58558K(1382400K), 0.0243907 secs] 1225641K->1109742K(2992128K), 0.0246
476 secs] [Times: user=0.09 sys=0.00, real=0.02 secs] 

2021-08-05T03:55:30.510+0800: 552746.926: [GC (Allocation Failure) 2021-08-05T03:55:30.510+0800: 552746.926: [ParNew (promotion failed): 1287358K->1277059K(1382400K), 0.0500869 secs]2021-08-05T03:5
5:30.560+0800: 552746.976: [CMS: 1051183K->1579488K(1609728K), 2.6962046 secs] 2338542K->1579488K(2992128K), [Metaspace: 133116K->133116K(1179648K)], 2.7467048 secs] [Times: user=2.66 sys=0.16, rea
l=2.74 secs] 

2021-08-05T03:55:33.260+0800: 552749.675: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1579488K(1609728K)] 1584181K(2992128K), 0.0039135 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-08-05T03:55:33.264+0800: 552749.680: [CMS-concurrent-mark-start]
2021-08-05T03:55:33.561+0800: 552749.977: [CMS-concurrent-mark: 0.268/0.297 secs] [Times: user=0.44 sys=0.09, real=0.30 secs] 
2021-08-05T03:55:33.561+0800: 552749.977: [CMS-concurrent-preclean-start]
2021-08-05T03:55:33.573+0800: 552749.989: [CMS-concurrent-preclean: 0.011/0.012 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
2021-08-05T03:55:33.573+0800: 552749.989: [CMS-concurrent-abortable-preclean-start]
2021-08-05T03:55:33.573+0800: 552749.989: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-08-05T03:55:33.576+0800: 552749.992: [GC (CMS Final Remark) [YG occupancy: 67314 K (1382400 K)]2021-08-05T03:55:33.576+0800: 552749.992: [Rescan (parallel) , 0.0106212 secs]2021-08-05T03:55:33.587+0800: 552750.002: [weak refs processing, 0.0017636 secs]2021-08-05T03:55:33.588+0800: 552750.004: [class unloading, 0.0495103 secs]2021-08-05T03:55:33.638+0800: 552750.054: [scrub symbol table, 0.0312748 secs]2021-08-05T03:55:33.669+0800: 552750.085: [scrub string table, 0.0020369 secs][1 CMS-remark: 1579488K(1609728K)] 1646802K(2992128K), 0.0955885 secs] [Times: user=0.13 sys=0.00, real=0.10 secs] 
2021-08-05T03:55:33.672+0800: 552750.088: [CMS-concurrent-sweep-start]
2021-08-05T03:55:33.975+0800: 552750.391: [CMS-concurrent-sweep: 0.303/0.303 secs] [Times: user=0.30 sys=0.01, real=0.30 secs] 
2021-08-05T03:55:33.975+0800: 552750.391: [CMS-concurrent-reset-start]
2021-08-05T03:55:33.979+0800: 552750.395: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

2021-08-05T03:55:35.981+0800: 552752.397: [GC (CMS Initial Mark) [1 CMS-initial-mark: 1412434K(1609728K)] 1494842K(2992128K), 0.0106662 secs] [Times: user=0.04 sys=0.00, real=0.01 secs] 
2021-08-05T03:55:35.992+0800: 552752.408: [CMS-concurrent-mark-start]
2021-08-05T03:55:36.244+0800: 552752.659: [CMS-concurrent-mark: 0.251/0.251 secs] [Times: user=0.26 sys=0.00, real=0.25 secs] 
2021-08-05T03:55:36.244+0800: 552752.660: [CMS-concurrent-preclean-start]
2021-08-05T03:55:36.252+0800: 552752.668: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2021-08-05T03:55:36.252+0800: 552752.668: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 
2021-08-05T03:55:41.254+0800: 552757.670: [CMS-concurrent-abortable-preclean: 0.389/5.002 secs] [Times: user=1.70 sys=0.13, real=5.00 secs] 
2021-08-05T03:55:41.257+0800: 552757.672: [GC (CMS Final Remark) [YG occupancy: 187783 K (1382400 K)]2021-08-05T03:55:41.257+0800: 552757.672: [Rescan (parallel) , 0.0255827 secs]2021-08-05T03:55:41.282+0800: 552757.698: [weak refs processing, 0.0001145 secs]2021-08-05T03:55:41.283+0800: 552757.698: [class unloading, 0.0512460 secs]2021-08-05T03:55:41.334+0800: 552757.749: [scrub symbol table, 0.0359631 secs]2021-08-05T03:55:41.370+0800: 552757.785: [scrub string table, 0.0021314 secs][1 CMS-remark: 1412434K(1609728K)] 1600217K(2992128K), 0.1153482 secs] [Times: user=0.19 sys=0.00, real=0.12 secs] 
2021-08-05T03:55:41.373+0800: 552757.788: [CMS-concurrent-sweep-start]
2021-08-05T03:55:41.711+0800: 552758.127: [CMS-concurrent-sweep: 0.334/0.338 secs] [Times: user=0.39 sys=0.02, real=0.34 secs] 
2021-08-05T03:55:41.711+0800: 552758.127: [CMS-concurrent-reset-start]
2021-08-05T03:55:41.715+0800: 552758.131: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 

2021-08-05T03:57:19.440+0800: 552855.855: [GC (Allocation Failure) 2021-08-05T03:57:19.440+0800: 552855.856: [ParNew: 1228800K->39395K(1382400K), 0.0197290 secs] 1472582K->283177K(2992128K), 0.0200263 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
2021-08-05T03:59:16.720+0800: 552973.135: [GC (Allocation Failure) 2021-08-05T03:59:16.720+0800: 552973.135: [ParNew: 1268195K->33425K(1382400K), 0.0252235 secs] 1511977K->277208K(2992128K), 0.0255503 secs] [Times: user=0.08 sys=0.01, real=0.02 secs] 
2021-08-05T04:00:57.738+0800: 553074.154: [GC (Allocation Failure) 2021-08-05T04:00:57.739+0800: 553074.154: [ParNew: 1262225K->51361K(1382400K), 0.0300787 secs] 1506008K->295143K(2992128K), 0.0303529 secs] [Times: user=0.09 sys=0.02, real=0.04 secs] 
2021-08-05T04:02:53.050+0800: 553189.466: [GC (Allocation Failure) 2021-08-05T04:02:53.051+0800: 553189.466: [ParNew: 1280161K->72744K(1382400K), 0.0473036 secs] 1523943K->316526K(2992128K), 0.0476385 secs] [Times: user=0.13 sys=0.00, real=0.04 secs] 
9月前