gc日志含义

gc日志

 

新生代gc 日志

[GC

Desired survivor size 8716288 bytes, new threshold 7 (max 15)

 

full gc 日志

1.461: [Full GC (System) [PSYoungGen: 4673K->0K(59712K)] [PSOldGen: 0K->4415K(136576K)]

 

时间为 JVM以启动时间为基准的相对时间

(full 0) 表示 full gc 执行次数

Heap before GC invocations=1  这个1表示gc次数

 

 

{Heap before GC invocations=1 (full 0):

 PSYoungGen      total 59712K, used 17462K [0x00000007c0000000, 0x00000007c42a0000, 0x0000000800000000)

  eden space 51200K, 34% used [0x00000007c0000000,0x00000007c110d9b8,0x00000007c3200000)

  from space 8512K, 0% used [0x00000007c3a50000,0x00000007c3a50000,0x00000007c42a0000)

  to   space 8512K, 0% used [0x00000007c3200000,0x00000007c3200000,0x00000007c3a50000)

 PSOldGen        total 136576K, used 0K [0x0000000740000000, 0x0000000748560000, 0x00000007c0000000)

  object space 136576K, 0% used [0x0000000740000000,0x0000000740000000,0x0000000748560000)

 PSPermGen       total 65536K, used 9703K [0x0000000738000000, 0x000000073c000000, 0x0000000740000000)

  object space 65536K, 14% used [0x0000000738000000,0x0000000738979e60,0x000000073c000000)

1.432: [GC

Desired survivor size 8716288 bytes, new threshold 7 (max 15)

 [PSYoungGen: 17462K->4673K(59712K)] 17462K->4673K(196288K), 0.0258330 secs] [Times: user=0.01 sys=0.00, real=0.03 secs] 

Heap after GC invocations=1 (full 0):

 PSYoungGen      total 59712K, used 4673K [0x00000007c0000000, 0x00000007c42a0000, 0x0000000800000000)

  eden space 51200K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007c3200000)

  from space 8512K, 54% used [0x00000007c3200000,0x00000007c3690760,0x00000007c3a50000)

  to   space 8512K, 0% used [0x00000007c3a50000,0x00000007c3a50000,0x00000007c42a0000)

 PSOldGen        total 136576K, used 0K [0x0000000740000000, 0x0000000748560000, 0x00000007c0000000)

  object space 136576K, 0% used [0x0000000740000000,0x0000000740000000,0x0000000748560000)

 PSPermGen       total 65536K, used 9703K [0x0000000738000000, 0x000000073c000000, 0x0000000740000000)

  object space 65536K, 14% used [0x0000000738000000,0x0000000738979e60,0x000000073c000000)

}

{Heap before GC invocations=2 (full 1):

 PSYoungGen      total 59712K, used 4673K [0x00000007c0000000, 0x00000007c42a0000, 0x0000000800000000)

  eden space 51200K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007c3200000)

  from space 8512K, 54% used [0x00000007c3200000,0x00000007c3690760,0x00000007c3a50000)

  to   space 8512K, 0% used [0x00000007c3a50000,0x00000007c3a50000,0x00000007c42a0000)

 PSOldGen        total 136576K, used 0K [0x0000000740000000, 0x0000000748560000, 0x00000007c0000000)

  object space 136576K, 0% used [0x0000000740000000,0x0000000740000000,0x0000000748560000)

 PSPermGen       total 65536K, used 9703K [0x0000000738000000, 0x000000073c000000, 0x0000000740000000)

  object space 65536K, 14% used [0x0000000738000000,0x0000000738979e60,0x000000073c000000)

1.461: [Full GC (System) [PSYoungGen: 4673K->0K(59712K)] [PSOldGen: 0K->4415K(136576K)] 4673K->4415K(196288K) [PSPermGen: 9703K->9703K(65536K)], 0.0232110 secs] [Times: user=0.03 sys=0.00, real=0.02 secs] 

Heap after GC invocations=2 (full 1):

 PSYoungGen      total 59712K, used 0K [0x00000007c0000000, 0x00000007c42a0000, 0x0000000800000000)

  eden space 51200K, 0% used [0x00000007c0000000,0x00000007c0000000,0x00000007c3200000)

  from space 8512K, 0% used [0x00000007c3200000,0x00000007c3200000,0x00000007c3a50000)

  to   space 8512K, 0% used [0x00000007c3a50000,0x00000007c3a50000,0x00000007c42a0000)

 PSOldGen        total 136576K, used 4415K [0x0000000740000000, 0x0000000748560000, 0x00000007c0000000)

  object space 136576K, 3% used [0x0000000740000000,0x000000074044ff80,0x0000000748560000)

 PSPermGen       total 65536K, used 9703K [0x0000000738000000, 0x000000073c000000, 0x0000000740000000)

  object space 65536K, 14% used [0x0000000738000000,0x0000000738979e60,0x000000073c000000)

}

 

 

 几乎所有的资料上说到打印JVM GC log的时候都会推荐一个参数： -XX:+PrintGCTimeStamps， 可该选项打印的是JVM以启动时间为基准的相对时间，对于troubleshooting来说非常困难。早在07年的时候就有人提出来并且早已fix，用法是使用 PrintGCDateStamps 代替PrintGCTimeStamps，打印出来的就是真实的日期了

 

服务器参数配置

JAVA_OPTS="-server -Xms200M -Xmx3072M  -XX:PermSize=64M -XX:MaxPermSize=128m -verbose:gc -Xloggc:../logs/gclog.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+HeapDumpOnOutOfMemoryError"

 

export JAVA_OPTS

 

---------------------------------------------------------

GC日志分析工具汇总

性能测试排查定位问题，分析调优过程中，会遇到要分析gc日志，人肉分析gc日志有时比较困难，相关图形化或命令行工具可以有效地帮助辅助分析。

Gc日志参数

通过在tomcat启动脚本中添加相关参数生成gc日志

-verbose.gc开关可显示GC的操作内容。打开它，可以显示最忙和最空闲收集行为发生的时间、收集前后的内存大小、收集需要的时间等。

打开-xx:+ printGCdetails开关，可以详细了解GC中的变化。

打开-XX: + PrintGCTimeStamps开关，可以了解这些垃圾收集发生的时间，自JVM启动以后以秒计量。

最后，通过-xx: + PrintHeapAtGC开关了解堆的更详细的信息。

为了了解新域的情况，可以通过-XX:=PrintTenuringDistribution开关了解获得使用期的对象权。

-Xloggc:$CATALINA_BASE/logs/gc.log gc日志产生的路径

XX:+PrintGCApplicationStoppedTime // 输出GC造成应用暂停的时间

-XX:+PrintGCDateStamps // GC发生的时间信息

 

Gc日志

日志中显示了gc发生的时间，young区回收情况，整体回收情况，fullGC情况，回收所消耗时间等

 

常用JVM参数

分析gc日志后，经常需要调整jvm内存相关参数，常用参数如下

-Xms：初始堆大小，默认为物理内存的1/64(<1GB)；默认(MinHeapFreeRatio参数可以调整)空余堆内存小于40%时，JVM就会增大堆直到-Xmx的最大限制

-Xmx：最大堆大小，默认(MaxHeapFreeRatio参数可以调整)空余堆内存大于70%时，JVM会减少堆直到 -Xms的最小限制

-Xmn：新生代的内存空间大小，注意：此处的大小是（eden+ 2 survivor space)。与jmap -heap中显示的New gen是不同的。整个堆大小=新生代大小 + 老生代大小 + 永久代大小。 
在保证堆大小不变的情况下，增大新生代后,将会减小老生代大小。此值对系统性能影响较大,Sun官方推荐配置为整个堆的3/8。

-XX:SurvivorRatio：新生代中Eden区域与Survivor区域的容量比值，默认值为8。两个Survivor区与一个Eden区的比值为2:8,一个Survivor区占整个年轻代的1/10。

-Xss：每个线程的堆栈大小。JDK5.0以后每个线程堆栈大小为1M,以前每个线程堆栈大小为256K。应根据应用的线程所需内存大小进行适当调整。在相同物理内存下,减小这个值能生成更多的线程。但是操作系统对一个进程内的线程数还是有限制的，不能无限生成，经验值在3000~5000左右。一般小的应用， 如果栈不是很深， 应该是128k够用的，大的应用建议使用256k。这个选项对性能影响比较大，需要严格的测试。和threadstacksize选项解释很类似,官方文档似乎没有解释,在论坛中有这样一句话:"-Xss is translated in a VM flag named ThreadStackSize”一般设置这个值就可以了。

-XX:PermSize：设置永久代(perm gen)初始值。默认值为物理内存的1/64。

-XX:MaxPermSize：设置持久代最大值。物理内存的1/4。

 

Gc日志分析工具

(1)GCHisto

http://java.net/projects/gchisto

直接点击gchisto.jar就可以运行，点add载入gc.log

统计了总共gc次数，youngGC次数，FullGC次数，次数的百分比，GC消耗的时间，百分比，平均消耗时间，消耗时间最小最大值等

统计的图形化表示

YoungGC,FullGC不同消耗时间上次数的分布图，勾选可以显示youngGC或fullGC单独的分布情况

 整个时间过程详细的gc情况，可以对整个过程进行剖析

 

 (2)GCLogViewer

http://code.google.com/p/gclogviewer/

点击run.bat运行

 整个过程gc情况的趋势图，还显示了gc类型，吞吐量，平均gc频率，内存变化趋势等

Tools里还能比较不同gc日志

(3)HPjmeter

 

获取地址 http://www.hp.com/go/java
参考文档 http://www.javaperformancetuning.com/tools/hpjtune/index.shtml

 

工具很强大，但只能打开由以下参数生成的GC log， -verbose:gc -Xloggc:gc.log,添加其他参数生成的gc.log无法打开。

 

(4)GCViewer

http://www.tagtraum.com/gcviewer.html

这个工具用的挺多的，但只能在JDK1.5以下的版本中运行，1.6以后没有对应。

(5)garbagecat

http://code.google.com/a/eclipselabs.org/p/garbagecat/wiki/Documentation

 

 

其它监控方法

Jvisualvm动态分析jvm内存情况和gc情况，插件：visualGC

 

 

  

jvisualvm还可以heapdump出对应hprof文件（默认存放路径：监控的服务器 /tmp下），利用相关工具，比如HPjmeter可以对其进行分析

grep Full gc.log粗略观察FullGC发生频率

jstat –gcutil [pid] [intervel] [count]

jmap -histo pid可以观测对象的个数和占用空间
jmap -heap pid可以观测jvm配置参数，堆内存各区使用情况

jprofiler,jmap dump出来用MAT分析

 

如果要分析的dump文件很大的话，就需要很多内存，很容易crash。

所以在启动时，我们应该加上一些参数： Java –Xms512M –Xmx1024M –Xss8M 

 

GC Analyzer

Analysis of VerboseGC Traces

http://glezen.org/gca/index.html

支持JDK 1.4.2

支持命令行和界面

 

PrintGCStats

GC日志分析脚本

http://chenjianjx.iteye.com/blog/1681347

 

参考：
http://blog.csdn.net/gzh0222/article/details/8223277

 

---------------------------------------------------

1.原始GC日志（通过JVM配置GC Print参数获取GC日志）

...

695.775: [GC 695.776: [ParNew: 130944K->0K(131008K), 0.0174100 secs] 432961K->302710K(786368K), 0.0175930 secs]
697.323: [GC [1 CMS-initial-mark: 302710K(655360K)] 348624K(786368K), 0.1140530 secs]
697.438: [CMS-concurrent-mark-start]
699.494: [GC 699.494: [ParNew: 130944K->0K(131008K), 0.0115290 secs] 433654K->303891K(786368K), 0.0116990 secs]
701.381: [CMS-concurrent-mark: 1.204/3.944 secs]
701.381: [CMS-concurrent-preclean-start]
701.382: [CMS-concurrent-preclean: 0.000/0.000 secs]
701.420: [CMS-concurrent-abortable-preclean-start]
701.420: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
703.302: [GC 703.302: [ParNew: 130944K->0K(131008K), 0.0161480 secs] 434835K->305889K(786368K), 0.0163490 secs]
705.202: [GC[YG occupancy: 68582 K (131008 K)]705.202: [Rescan (parallel) , 0.1094800 secs]705.312: [weak refs processing, 0.0446420 secs] [1 CMS-remark: 305889K(655360K)] 374472K(786368K), 0.1543650 secs]
705.360: [CMS-concurrent-sweep-start]
705.644: [CMS-concurrent-sweep: 0.284/0.284 secs]
705.644: [CMS-concurrent-reset-start]
705.654: [CMS-concurrent-reset: 0.010/0.010 secs]
706.985: [GC 706.985: [ParNew: 130924K->0K(131008K), 0.0193060 secs] 432106K->302870K(786368K), 0.0195480 secs]
708.540: [GC [1 CMS-initial-mark: 302870K(655360K)] 350092K(786368K), 0.1140590 secs]
708.654: [CMS-concurrent-mark-start]
710.647: [GC 710.647: [ParNew: 130944K->0K(131008K), 0.0081390 secs] 433814K->303960K(786368K), 0.0083430 secs]
712.560: [CMS-concurrent-mark: 1.314/3.906 secs]
712.560: [CMS-concurrent-preclean-start]
712.560: [CMS-concurrent-preclean: 0.000/0.000 secs]
712.615: [CMS-concurrent-abortable-preclean-start]
712.615: [CMS-concurrent-abortable-preclean: 0.000/0.000 secs]
713.567: [GC 713.567: [ParNew: 130944K->0K(131008K), 0.0104890 secs] 434904K->305163K(786368K), 0.0107090 secs]
715.109: [GC[YG occupancy: 68948 K (131008 K)]715.109: [Rescan (parallel) , 0.0884690 secs]715.198: [weak refs processing, 0.0441790 secs] [1 CMS-remark: 305163K(655360K)] 374111K(786368K), 0.1329350 secs]
715.243: [CMS-concurrent-sweep-start]
715.445: [CMS-concurrent-sweep: 0.203/0.203 secs]
715.445: [CMS-concurrent-reset-start]
715.454: [CMS-concurrent-reset: 0.009/0.009 secs]

...

2.日志分析报告

针对原始GC日志，分别用下面两种工具做了分析，其中gcviewer分析还是比较具体的，就是解析日志时会有些异常，但不影响最后的结果。

（1）通过gcviewer分析：

 

图1（顶部的黑色线都代表Full GC，也可以理解为Major GC，是根据日志中的CMS GC统计的；底部灰色线代表的是Minor GC）

 

图2

 

图3

可以看到Full GC非常多，占所有pause时间比达到65.9%，这是有问题的，GC应该尽可能在年轻代完成，而不是到年老代，这个在第3部分参数说明中会提到。

（2）通过GarbageCat分析：

========================================
SUMMARY:
========================================
# GC Events: 172925
GC Event Types: CMS_INITIAL_MARK, CMS_CONCURRENT, CMS_SERIAL_OLD_CONCURRENT_MODE_FAILURE, PAR_NEW, CMS_REMARK
Max Heap Space: 1079084K
Max Heap Occupancy: 716725K
Max Perm Space: 98304K
Max Perm Occupancy: 8993K
Throughput: 97%
Max Pause: 426 ms
Total Pause: 9033244 ms
First Timestamp: 250 ms
Last Timestamp: 342994691 ms

从这里主要看pause time时间，分析报告中还有一部分不能处理的，这些日志现在还没找到最终原因：

========================================
30 UNIDENTIFIED LOG LINE(S):
========================================
39629.723: [Full GC 39629.723: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor6720]
40724.189: [Full GC 40724.189: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1945]
40785.929: [Full GC 40785.929: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10169]
40922.428: [Full GC 40922.428: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor10175]
124477.019: [Full GC 124477.019: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor33989]
124997.427: [Full GC 124997.427: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34622]
125059.257: [Full GC 125059.257: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34638]
125348.006: [Full GC 125348.006: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor34644]
125940.674: [Full GC 125940.674: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor2017]
126047.093: [Full GC 126047.093: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor5743]
128938.724: [Full GC 128938.724: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor5715]
209586.704: [Full GC 209586.704: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58696]
210272.871: [Full GC 210272.872: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor5749]
211428.317: [Full GC 211428.318: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor7545]
212198.995: [Full GC 212198.995: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedMethodAccessor5806]
212408.355: [Full GC 212408.355: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58795]
212525.304: [Full GC 212525.304: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58807]
212819.763: [Full GC 212819.763: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58817]
212881.623: [Full GC 212881.623: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58821]
214567.777: [Full GC 214567.778: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor1643]
214980.856: [Full GC 214980.856: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58897]
215119.546: [Full GC 215119.546: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor58903]
294794.469: [Full GC 294794.469: [CMS[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81521]
298186.036: [Full GC 298186.036: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81595]
300171.660: [Full GC 300171.660: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81708]
300318.420: [Full GC 300318.420: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81738]
300380.550: [Full GC 300380.550: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81772]
300756.398: [Full GC 300756.398: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81744]
300818.348: [Full GC 300818.348: [CMS (concurrent mode failure)[Unloading class sun.reflect.GeneratedSerializationConstructorAccessor81788]
301812.025: [Full GC 301812.025: [CMS[Unloading class sun.reflect.GeneratedMethodAccessor10606]

 

3.问题根源（当前参数配置及说明，其中红色标注的是设置不妥的地方）

 98％的java对象，在创建之后不久就变成了非活动对象；只有2％的对象，会在长时间一直处于活动状态。major gc需要的时间比minor gc长的多，所以我们要减少major gc次数，提高minor gc的效率，尽量将非活动对象消灭在年轻代。

针对上述分析报告，从JVM当前参数配置中找到了些原因，如下：

-Xms768m -Xmx1280m  jvm堆的最小值和最大值设置，一般设成相同值，避免频繁分配堆空间

-XX:NewSize=128m -XX:MaxNewSize=128m  年轻代最小值和最大值设置（年轻代设定了，年老代也就定了），也可以用参数-XX:NewRatio=4，年老代和年轻代的大小比，这里128m有点小了，官方建议的是heap的3/8，差不多280m

-XX:PermSize=96m -XX:MaxPermSize=128m 持久代最小值和最大值设置

-XX:MaxTenuringThreshold=0  经过多少次minor gc 后进入年老代,设置为0的话直接进入年老代，这是不太合理的，正常应该在年轻代多呆一段时间，真正需要到年老代的才转过去

-XX:SurvivorRatio=20000  年轻代中eden和一块suvivor区的空间比例，这里设置成20000有问题，suvivor区空间几乎为0，一次minor gc后基本都转到年老代了，年轻代没有起到过滤左右

-XX:+UseParNewGC  年轻代采用并行gc策略，JDK5.0以上,JVM会根据系统配置自行设置,所以无需再设置此值。使用多线程收集，提高吞吐量（-XX:ParallelGCThreads 并行收集器的线程数，此值最好配置与处理器数目相等，如果超过当前cpu数，会加大机器负载）

-XX:+UseConcMarkSweepGC  年老代采用并发gc策略，和应用程序并发执行，减少pause time，但是需要更大的堆区，因为并发执行，有碎片（-XX:+UseParallelOldGC 年老代垃圾收集方式为并行收集，这个是JAVA 6出现的参数选项）

 -XX:+CMSPermGenSweepingEnabled  为了避免Perm区满引起的full gc，建议开启CMS回收Perm区选项

 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps  打印gc日志

 -XX:CMSInitiatingOccupancyFraction=1 年老代使用空间比达到这个值时开始cms gc,默认是在年老代占满68%的时候开始进行CMS收集，这里设置成1是不合理的，会导致CMS GC频繁发生，从gc日志里可以看出来，CMS GC和minor GC几乎一样多

 -XX:+CMSIncrementalMode 启动i-CMS模式，增量模式，将cms gc过程分成6个阶段，其中阶段initial Mark和remark时需要pause，这6个阶段在两次minor gc的间隔期执行，具体执行起止时间由下面两个参数决定。拆分成小阶段增量执行时，可以避免应用被中断时间过长，极端情况是如果只有一个cpu，那么得等全部做完这6个阶段才能释放cpu，如果是多cpu这个模式开启与否应该影响不大。

-XX:CMSIncrementalDutyCycleMin=10 默认值10 启动CMS的下线

-XX:CMSIncrementalDutyCycle=30 默认值50 启动CMS的上线

-XX:+UseCMSCompactAtFullCollection  在FULL GC的时候， 对年老代的压缩。CMS是不会移动内存的， 因此这个非常容易产生碎片， 导致内存不够用， 因此， 内存的压缩这个时候就会被启用。 可能会影响性能,但是可以消除碎片，增加这个参数是个好习惯。

-XX:CMSFullGCsBeforeCompaction=0  上面配置开启的情况下,这里设置多少次Full GC后,对年老代进行压缩，这里设置成0不知道什么意思，可以根据线上full gc 的频率确定，频率高，这个值可以大点，比如5，反之频率低，这个值可以小点，比如1

-XX:CMSMarkStackSize=8M

-XX:CMSMarkStackSizeMax=32M