[讨论] GC文件分析

shu672725 2012-06-12

启动参数:java -Xloggc:gc-Autodeliver.vgc -d64 -Xms4g -Xmx4g -Xmn1g -XX:PermSize=256m -XX:MaxPermSize=512m -server -Xnoclassgc -XX:+UseParNewGC -XX:ParallelGCThreads=12 -XX:MaxTenuringThreshold=6 -XX:SurvivorRatio=5 -XX:+UseConcMarkSweepGC  -XX:-CMSParallelRemarkEnabled -XX:CMSInitiatingOccupancyFraction=65 -XX:+UseCMSInitiatingOccupancyOnly  -XX:+UseCMSCompactAtFullCollection  -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -Dsun.rmi.dgc.client.gcInterval=36000009999 -Dsun.rmi.dgc.server.gcInterval=36000009999 -XX:+PrintGCDetails -Dfile.encoding=GBK  -cp $JARS 

有几点关于CMS的问题不是很清楚,想请教一下,正如图所示: 
1、每一次同一时间点上都有两个CMS标志,这个分别代表的是什么,是CMS中的那两个停顿过程吗? 
2、根据启动参数老年代应该有3g,按说老年代占用65%的时候会触发CMS,但是现在几百兆的时候就会去触发,感觉也应该不会是perm触发的CMS吧,为什么每次触发的点还一直变化,如果系统稳定运行的话这个点应该是基本一致的吧。 
3、到后面CMS区域都成块状的了,这个是说明CMS一直在执行吗,如果一直在执行岂不是会频繁stop the world,但是现在系统还在正常运行着。 

 

 

xiaoyu 2012-06-12
楼主最好给出gc log...
shu672725 2012-06-12
xiaoyu 写道
楼主最好给出gc log...

太大了100多M,这从这个图基本上也能看出gc log 内容
xiaoyu 2012-06-12
shu672725 写道
xiaoyu 写道
楼主最好给出gc log...

太大了100多M,这从这个图基本上也能看出gc log 内容


给出某段就可以了. 例如 你说的各阶段 cms log 等
RednaxelaFX 2012-06-12
请问这是啥工具的截图?不知道是啥工具的话无法判断图上的标志是什么。
另外这个工具必然有各种小毛病。例如说CMS是不能跟“Parallel Scavenge”混搭使用的,而这图里把这俩显示成混在一起,肯定有写错(多半是吧ParNew写成ParallelScavenge了)
shu672725 2012-06-12
RednaxelaFX 写道
请问这是啥工具的截图?不知道是啥工具的话无法判断图上的标志是什么。
另外这个工具必然有各种小毛病。例如说CMS是不能跟“Parallel Scavenge”混搭使用的,而这图里把这俩显示成混在一起,肯定有写错(多半是吧ParNew写成ParallelScavenge了)


使用的HPjmeter,恩这个是ParNew启动参数里面配置的也是这个
shu672725 2012-06-12
xiaoyu 写道
shu672725 写道
xiaoyu 写道
楼主最好给出gc log...

太大了100多M,这从这个图基本上也能看出gc log 内容


给出某段就可以了. 例如 你说的各阶段 cms log 等



第一次CMS的:
523073.465: [GC [1 CMS-initial-mark: 704288K(3938752K)] 791557K(4157824K), 0.2279523 secs] [Times: user=0.23 sys=0.00, real=0.23 secs]
523073.693: [CMS-concurrent-mark-start]
523076.035: [CMS-concurrent-mark: 2.342/2.342 secs] [Times: user=0.00 sys=0.00, real=2.34 secs]
523076.035: [CMS-concurrent-preclean-start]
523076.068: [CMS-concurrent-preclean: 0.033/0.033 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
523076.068: [CMS-concurrent-abortable-preclean-start]
523079.207: [GC 523079.207: [ParNew: 183168K->1247K(219072K), 0.0528393 secs] 887457K->705536K(4157824K), 0.0531568 secs] [Times: user=0.00 sys=0.00, real=0.05 secs]
CMS: abort preclean due to time 523081.070: [CMS-concurrent-abortable-preclean: 0.914/5.002 secs] [Times: user=0.89 sys=0.00, real=5.00 secs]
523081.076: [GC[YG occupancy: 72997 K (219072 K)]523081.077: [Rescan (non-parallel) 523081.077: [grey object rescan, 0.0062092 secs]523081.083: [root rescan, 0.0974809 secs], 0.1037933 secs]523081.180: [weak refs processing, 0.1107287 secs]523081.291: [class unloading, 0.0502101 secs]523081.342: [scrub symbol & string tables, 0.0241295 secs] [1 CMS-remark: 704289K(3938752K)] 777286K(4157824K), 0.4065691 secs] [Times: user=0.40 sys=0.00, real=0.41 secs]
523081.484: [CMS-concurrent-sweep-start]
523083.355: [CMS-concurrent-sweep: 1.871/1.871 secs] [Times: user=1.87 sys=0.00, real=1.87 secs]
523083.382: [CMS-concurrent-reset-start]
523083.455: [CMS-concurrent-reset: 0.073/0.073 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]
第二次CMS的:

599334.014: [GC [1 CMS-initial-mark: 313549K(3938752K)] 428098K(4157824K), 0.3165110 secs] [Times: user=0.32 sys=0.00, real=0.32 secs]
599334.331: [CMS-concurrent-mark-start]
599336.785: [CMS-concurrent-mark: 2.454/2.454 secs] [Times: user=0.00 sys=0.00, real=2.45 secs]
599336.785: [CMS-concurrent-preclean-start]
599336.825: [CMS-concurrent-preclean: 0.040/0.040 secs] [Times: user=0.04 sys=0.00, real=0.04 secs]
599336.825: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 599341.857: [CMS-concurrent-abortable-preclean: 0.857/5.031 secs] [Times: user=0.84 sys=0.00, real=5.03 secs]
599341.864: [GC[YG occupancy: 172976 K (219072 K)]599341.864: [Rescan (non-parallel) 599341.864: [grey object rescan, 0.0086597 secs]599341.872: [root rescan, 0.4480893 secs], 0.4568828 secs]599342.321: [weak refs processing, 0.0602911 secs]599342.381: [class unloading, 0.0575807 secs]599342.439: [scrub symbol & string tables, 0.0213210 secs] [1 CMS-remark: 313549K(3938752K)] 486525K(4157824K), 0.7027196 secs] [Times: user=0.70 sys=0.00, real=0.70 secs]
599342.567: [CMS-concurrent-sweep-start]
599343.997: [CMS-concurrent-sweep: 1.430/1.430 secs] [Times: user=1.43 sys=0.00, real=1.43 secs]
599344.034: [CMS-concurrent-reset-start]
599344.107: [CMS-concurrent-reset: 0.074/0.074 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]

这个就是到块状区域的时候的:
[GC [1 CMS-initial-mark: 629159K(3938752K)] 758798K(4157824K), 0.3749705 secs] [Times: user=0.37 sys=0.00, real=0.38 secs]
1451829.898: [CMS-concurrent-mark-start]
1451835.237: [GC 1451835.238: [ParNew: 183166K->1970K(219072K), 0.1162101 secs] 812325K->631131K(4157824K), 0.1165066 secs] [Times: user=0.01 sys=0.00, real=0.12 secs]
1451837.570: [CMS-concurrent-mark: 6.416/7.673 secs] [Times: user=0.00 sys=0.00, real=7.67 secs]
1451837.571: [CMS-concurrent-preclean-start]
1451837.642: [CMS-concurrent-preclean: 0.070/0.071 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]
1451837.642: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 1451842.723: [CMS-concurrent-abortable-preclean: 1.048/5.081 secs] [Times: user=1.00 sys=0.00, real=5.08 secs]
1451842.772: [GC[YG occupancy: 61385 K (219072 K)]1451842.772: [Rescan (non-parallel) 1451842.772: [grey object rescan, 0.0072141 secs]1451842.780: [root rescan, 0.2873247 secs], 0.2946969 secs]1451843.067: [weak refs processing, 0.1424610 secs]1451843.210: [class unloading, 0.1034974 secs]1451843.313: [scrub symbol & string tables, 0.0253252 secs] [1 CMS-remark: 629160K(3938752K)] 690545K(4157824K), 0.6809959 secs] [Times: user=0.67 sys=0.00, real=0.68 secs]
1451843.454: [CMS-concurrent-sweep-start]
1451844.926: [CMS-concurrent-sweep: 1.472/1.472 secs] [Times: user=1.45 sys=0.00, real=1.47 secs]
1451844.926: [CMS-concurrent-reset-start]
1451845.001: [CMS-concurrent-reset: 0.074/0.074 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]
1451847.031: [GC [1 CMS-initial-mark: 528324K(3938752K)] 640576K(4157824K), 0.3422740 secs] [Times: user=0.34 sys=0.00, real=0.34 secs]
1451847.374: [CMS-concurrent-mark-start]
1451853.698: [CMS-concurrent-mark: 6.324/6.324 secs] [Times: user=0.00 sys=0.00, real=6.32 secs]
1451853.698: [CMS-concurrent-preclean-start]
1451853.764: [CMS-concurrent-preclean: 0.063/0.066 secs] [Times: user=0.07 sys=0.00, real=0.07 secs]
1451853.764: [CMS-concurrent-abortable-preclean-start]
1451857.651: [GC 1451857.651: [ParNew: 184560K->2014K(219072K), 0.1320031 secs] 712885K->530339K(4157824K), 0.1322805 secs] [Times: user=0.01 sys=0.00, real=0.13 secs]
1451858.129: [CMS-concurrent-abortable-preclean: 0.828/4.365 secs] [Times: user=0.83 sys=0.00, real=4.36 secs]
1451858.149: [GC[YG occupancy: 100059 K (219072 K)]1451858.149: [Rescan (non-parallel) 1451858.149: [grey object rescan, 0.0073270 secs]1451858.156: [root rescan, 0.1816904 secs], 0.1891331 secs]1451858.338: [weak refs processing, 0.1142740 secs]1451858.452: [class unloading, 0.1034806 secs]1451858.556: [scrub symbol & string tables, 0.0264522 secs] [1 CMS-remark: 528325K(3938752K)] 628384K(4157824K), 0.5468494 secs] [Times: user=0.54 sys=0.00, real=0.55 secs]
1451858.696: [CMS-concurrent-sweep-start]
1451860.040: [CMS-concurrent-sweep: 1.344/1.344 secs] [Times: user=1.34 sys=0.00, real=1.34 secs]
1451860.040: [CMS-concurrent-reset-start]
1451860.116: [CMS-concurrent-reset: 0.076/0.076 secs] [Times: user=0.08 sys=0.00, real=0.08 secs]
1451862.177: [GC [1 CMS-initial-mark: 527809K(3938752K)] 677799K(4157824K), 0.2800060 secs] [Times: user=0.27 sys=0.00, real=0.28 secs]

Global site tag (gtag.js) - Google Analytics