集群中RegionServer hadoopserver03 的GC日志分析

约定不等于承诺〃 2022-05-23 01:11 124阅读 0赞

集群中RegionServer hadoopserver03 的GC日志分析  
Java HotSpot(TM) 64-Bit Server VM (25.71-b15) for linux-amd64 JRE (1.8.0\_71-b15), built on Dec 22 2015 18:21:33 by "java\_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)  
Memory: 4k page, physical 65948796k(13819668k free), swap 4194296k(3978176k free)  
CommandLine flags: -XX:CMSInitiatingOccupancyFraction=70 -XX:+CMSParallelRemarkEnabled -XX:InitialHeapSize=10737418240 -XX:MaxHeapSize=10737418240 -XX:MaxNewSize=1134141440 -XX:MaxTenuringThreshold=6 -XX:NewSize=1134141440 -XX:OldPLABSize=16 -XX:OldSize=2268282880 -XX:OnOutOfMemoryError=kill -9 %p -XX:OnOutOfMemoryError=/opt/cm-5.5.0/lib64/cmf/service/common/killparent.sh -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC   
  
  
3.749: \[GC (Allocation Failure) 3.749: \[ParNew: 886080K->27036K(996800K), 0.0516041 secs\] 886080K->27036K(10375040K), 0.0518951 secs\] \[Times: user=0.30 sys=0.01, real=0.05 secs\]   
  
  
3.802: \[GC (CMS Initial Mark) \[1 CMS-initial-mark: 0K(9378240K)\] 44758K(10375040K), 0.0044939 secs\]   
\[Times: user=0.02 sys=0.01, real=0.00 secs\]    【1.初始标记，暂停JVM】  
  
  
3.806: \[CMS-concurrent-mark-start\]  
3.810: \[CMS-concurrent-mark: 0.004/0.004 secs\] \[Times: user=0.02 sys=0.00, real=0.00 secs\]   【2.并发标记】  
  
  
3.810: \[CMS-concurrent-preclean-start\]  
3.834: \[CMS-concurrent-preclean: 0.023/0.023 secs\] \[Times: user=0.14 sys=0.01, real=0.03 secs\]  【3.并发预清理】  
  
  
3.834: \[CMS-concurrent-abortable-preclean-start\]  
5.819: \[CMS-concurrent-abortable-preclean: 1.671/1.985 secs\] \[Times: user=7.80 sys=0.36, real=1.98 secs\]   
5.819: \[GC (CMS Final Remark) \[YG occupancy: 473632 K (996800 K)\]5.820: \[Rescan (parallel) , 0.0196566 secs\]5.839: \[weak refs processing, 0.0000512 secs\]5.839: \[class unloading, 0.0084837 secs\]5.848: \[scrub symbol table, 0.0120085 secs\]5.860: \[scrub string table, 0.0006323 secs\]\[1 CMS-remark: 0K(9378240K)\] 473632K(10375040K), 0.0429900 secs\]   
\[Times: user=0.24 sys=0.00, real=0.05 secs\]    【4.重新标记，暂停JVM】  
  
  
5.863: \[CMS-concurrent-sweep-start\]  
5.863: \[CMS-concurrent-sweep: 0.000/0.000 secs\] \[Times: user=0.00 sys=0.00, real=0.00 secs\]  【5.并发清除】  
  
  
5.863: \[CMS-concurrent-reset-start\]  
5.931: \[CMS-concurrent-reset: 0.065/0.068 secs\] \[Times: user=0.16 sys=0.07, real=0.07 secs\]    【6.并发重置】  
  
  
11.585: \[GC (Allocation Failure) 11.585: \[ParNew: 913116K->51842K(996800K), 0.0485967 secs\] 913116K->51842K(10375040K), 0.0490776 secs\] \[Times: user=0.44 sys=0.06, real=0.05 secs\]   
  
  
248.307: \[GC (Allocation Failure) 248.308: \[ParNew: 937922K->110720K(996800K), 0.0618053 secs\] 937922K->114333K(10375040K), 0.0623409 secs\] \[Times: user=0.65 sys=0.04, real=0.07 secs\]             【7. 新生代使用ParNew并行收集器,注意,这里的Allocation Failure是正常现象,表明Eden区已满,无法继续分配新对象,需要进行一次Minor GC】  
，，  
  
  
CMS Initial Mark 花费：0.0044939  
  
  
CMS-remark:      花费：0.0429900  
共花费：0.04748  \* 1000 = 47 毫秒  
  
  
但是出现了下面问题：  
  
  
11.585: \[GC (Allocation Failure)   
11.585: \[ParNew: 913116K->51842K(996800K), 0.0485967 secs\]   
                 913116K->51842K(10375040K), 0.0490776 secs\]   
\[Times: user=0.44 sys=0.06, real=0.05 secs\]   
  
  
下面每个参数说明：  
2018-05-30T14:45:37.987-0200  (1)  
248.307:  (2)  
\[GC   用来区分 Minor GC 还是 Full GC 的标志。GC表明这是一次小型GC(Minor GC)  
(Allocation Failure)   触发 GC 的原因。本次GC事件, 是由于年轻代中没有空间来存放新的数据结构引起的。  
248.308: \[ParNew:   垃圾收集器的名称 . 这个神秘的名字表示的是在年轻代中使用的: 单线程, 标记-复制(mark-copy), 全线暂停(STW) 垃圾收集器。  
937922K->110720K  在垃圾收集之前和之后年轻代的使用量。  
(996800K)  年轻代总的空间大小。  
, 0.0618053 secs\] 937922K->114333K  在垃圾收集之前和之后整个堆内存的使用情况。  
(10375040K)  可用JAVA堆的总空间大小。  
, 0.0623409 secs   GC事件持续的时间,以秒为单位。  
\]\[Times: user=0.65 sys=0.04, real=0.07 secs\]  (11) GC事件的持续时间, 通过三个部分来衡量:  
  
  
user – 在此次垃圾回收过程中, 所有 GC线程所消耗的CPU时间之和。  
sys – GC过程中中操作系统调用和系统等待事件所消耗的时间。  
real – 应用程序暂停的时间。