jvm gc日志分析

JVM的GC日志的主要参数包括如下几个:
-XX:+PrintGC 输出GC日志
-XX:+PrintGCDetails 输出GC的详细日志
-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)
-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-XX:+PrintGCApplicationStoppedTime // 输出GC造成应用暂停的时间
-Xloggc:../logs/gc.log 日志文件的输出路径
XX:+PrintTenuringDistribution输出的方式是观察在每一个岁数上面,对象的存活的数量,以及其增减情况,以及HotSpot VM计算的任期阀值是不是等于或者近似于设定的最大任期阀值。


1、一个小小实例:

做了如下启动参数:

-XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps  
打印出来的日志为:

0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]  
1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]  
2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  
4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  
5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]  
7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]  
1)我们取倒数第二条记录分析一下各个字段都代表了什么含义:

5.617(时间戳): [GC(Young GC) 5.617(时间戳): [ParNew(GC的区域): 43296K(垃圾回收前的大小)->7006K(垃圾回收以后的大小)(47808K)(该区域总大小), 0.0136826 secs(回收时间)] 44992K(堆区垃圾回收前的大小)->8702K(堆区垃圾回收后的大小)(252608K)(堆区总大小), 0.0137904 secs(回收时间)] [Times: user=0.03(GC用户耗时) sys=0.00(GC系统耗时), real=0.02 secs(GC实际耗时)]  


2)我们再对数据做一个简单的分析

从最后一条GC记录中我们可以看到 Young GC回收了 45278-6723=38555K的内存

Heap区通过这次回收总共减少了 46974-10551=36423K的内存。

38555-36423=2132K说明通过该次Young GC有2132K的内存被移动到了Old Gen,

 我们来验证一下

在最后一次Young GC的回收以前 Old Gen的大小为8702-7006=1696

回收以后Old Gen的内存使用为10551-6723=3828

Old Gen在该次Young GC以后内存增加了3828-1696=2132K 与预计的相符


2、分析各个字段含义:

1)最前面的数字 4.231 和 4.445 代表虚拟机启动以来的秒数;

2)[GC 和 [Full GC 是垃圾回收的停顿类型,而不是区分是新生代还是年老代,如果有 Full 说明发生了Stop-The-World 。如果是调用 System.gc() 触发的,那么将显示的是 [Full GC (System) 。

3)接下来的 [DefNew[Tenured[Perm 表示 GC 发生的区域,区域的名称与使用的 GC 收集器相关:

  •  Serial 收集器中新生代名为 “Default New Generation”,显示的名字为 “[DefNew”;
  •  对于ParNew收集器,显示的是 “[ParNew”,表示 “Parallel New Generation”;
  •  对于 Parallel Scavenge 收集器,新生代名为 “PSYoungGen”。

 年老代和永久代也相同,名称都由收集器决定。

4)方括号内部显示的 “4928K->512K(4928K)” 表示 “GC 前该区域已使用容量 -> GC 后该区域已使用容量 (该区域内存总容量) ”。

5)再往后的 “0.0044047 secs” 表示该区域GC所用时间,单位是秒。

6)再往后的 “6835K->3468K(15872K)” 表示 “GC 前Java堆已使用容量 -> GC后Java堆已使用容量 (Java堆总容量)”。

7)再往后的 “0.0045291 secs” 是Java堆GC所用的总时间。

8)最后的 “[Times: user=0.00 sys=0.00, real=0.00 secs]” 分别代表 用户态消耗的CPU时间、内核态消耗的CPU时间 和 操作从开始到结束所经过的墙钟时间。墙钟时间包括各种非运算的等待耗时,如IO等待、线程阻塞。CPU时间不包括等待时间,当系统有多核时,多线程操作会叠加这些CPU时间,所以user或sys时间会超过real时间

3、例子1:

package jvm;
public class PrintGCDetails2
{
    /**
     * -Xms60m -Xmx60m -Xmn20m -XX:NewRatio=2 ( 若 Xms = Xmx, 并且设定了 Xmn,
     * 那么该项配置就不需要配置了 ) -XX:SurvivorRatio=8 -XX:PermSize=30m -XX:MaxPermSize=30m
     * -XX:+PrintGCDetails
     */
    public static void main(String[] args)
    {
        new PrintGCDetails2().doTest();
    }
 
    public void doTest()
    {
        Integer M = new Integer(1024 * 1024 * 1); // 单位, 兆(M)
        byte[] bytes = new byte[1 * M]; // 申请 1M 大小的内存空间
        bytes = null; // 断开引用链
        System.gc(); // 通知 GC 收集垃圾
        System.out.println();
        bytes = new byte[1 * M]; // 重新申请 1M 大小的内存空间
        bytes = new byte[1 * M]; // 再次申请 1M 大小的内存空间
        System.gc();
        System.out.println();
    }
}
运行结果:

[GC [PSYoungGen: 2007K->568K(18432K)] 2007K->568K(59392K), 0.0059377 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[Full GC [PSYoungGen: 568K->0K(18432K)] [ParOldGen: 0K->479K(40960K)] 568K->479K(59392K) [PSPermGen: 2484K->2483K(30720K)], 0.0223249 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
 
[GC [PSYoungGen: 3031K->1056K(18432K)] 3510K->1535K(59392K), 0.0140169 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 
[Full GC [PSYoungGen: 1056K->0K(18432K)] [ParOldGen: 479K->1503K(40960K)] 1535K->1503K(59392K) [PSPermGen: 2486K->2486K(30720K)], 0.0119497 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
 
Heap
 PSYoungGen      total 18432K, used 163K [0x00000000fec00000, 0x0000000100000000, 0x0000000100000000)
  eden space 16384K, 1% used [0x00000000fec00000,0x00000000fec28ff0,0x00000000ffc00000)
  from space 2048K, 0% used [0x00000000ffe00000,0x00000000ffe00000,0x0000000100000000)
  to   space 2048K, 0% used [0x00000000ffc00000,0x00000000ffc00000,0x00000000ffe00000)
 ParOldGen       total 40960K, used 1503K [0x00000000fc400000, 0x00000000fec00000, 0x00000000fec00000)
  object space 40960K, 3% used [0x00000000fc400000,0x00000000fc577e10,0x00000000fec00000)
 PSPermGen       total 30720K, used 2493K [0x00000000fa600000, 0x00000000fc400000, 0x00000000fc400000)
  object space 30720K, 8% used [0x00000000fa600000,0x00000000fa86f4f0,0x00000000fc400000)

从打印结果可以看出,堆中新生代的内存空间为 18432K ( 约 18M ),eden 的内存空间为 16384K ( 约 16M),from / to survivor 的内存空间为 2048K ( 约 2M)。
这里所配置的 Xmn 为 20M,也就是指定了新生代的内存空间为 20M,可是从打印的堆信息来看,新生代怎么就只有 18M 呢? 另外的 2M 哪里去了?
别急,是这样的。新生代 = eden + from + to = 16 + 2 + 2 = 20M,可见新生代的内存空间确实是按 Xmn 参数分配得到的。
而且这里指定了 SurvivorRatio = 8,因此,eden = 8/10 的新生代空间 = 8/10 * 20 = 16M。from = to = 1/10 的新生代空间 = 1/10 * 20 = 2M。
堆信息中新生代的 total 18432K 是这样来的: eden + 1 个 survivor = 16384K + 2048K = 18432K,即约为 18M。
因为 jvm 每次只是用新生代中的 eden 和 一个 survivor,因此新生代实际的可用内存空间大小为所指定的 90%。
因此可以知道,这里新生代的内存空间指的是新生代可用的总的内存空间,而不是指整个新生代的空间大小。
另外,可以看出老年代的内存空间为 40960K ( 约 40M ),堆大小 = 新生代 + 老年代。因此在这里,老年代 = 堆大小 – 新生代 = 60 – 20 = 40M。
最后,这里还指定了 PermSize = 30m,PermGen 即永久代 ( 方法区 ),它还有一个名字,叫非堆,主要用来存储由 jvm 加载的类文件信息、常量、静态变量等。

参考:

http://blog.csdn.net/doc_sgl/article/details/46594123

http://www.importnew.com/19593.html


4、常用的gc工具:

1)gcview:

下载地址:http://www.tagtraum.com/gcviewer-download.html (官网的只支持到jdk1.4)

这个地址是网上找的,可以支持jdk更高版本(http://download.csdn.net/detail/liuxiao723846/9856875)

打开后,把gc日志导入,然后可以看到下面的图


第一个标签页就是Chart,这也是最可以直观看出有没有问题的地方,如上图所示,这个日志反应了gc一直在不停的做新生带的回收,并且老年代的使用率一直在增加。图中整个高度为JVM总的内存大小,也就是989.9M,从右侧的Summary也可以看出。其中的紫色部分为老年代的大小,黄色部分是新生带的大小。不同颜色的线和图块的含义可以从菜单看出,如下图:


第二个tab是Event Dtails,可以看出各种GC的次数和时间间隔,以及效果:



2)gchisto

也是一款不错的可视化工具,不过我试了几次都无法解析gc日志,可能是我下的版本不对。

3)GCLogViewer:

这个没有试过,有兴趣的可以试一下。

下载地址(https://code.google.com/archive/p/gclogviewer/)官方这个版本无法运行在64位jdk上。

下面这个版本是网上找的,可以运行在64位jdk上(在我的资源页面下载)

相关文章
相关标签/搜索