欢迎您光临本小站。希望您在这里可以找到自己想要的信息。。。

GC日志分析

java water 4267℃ 0评论

JVM的GC日志的主要参数包括如下几个:

-XX:+PrintGC 输出GC日志

-XX:+PrintGCDetails 输出GC的详细日志

-XX:+PrintGCTimeStamps 输出GC的时间戳(以基准时间的形式)

-XX:+PrintGCDateStamps 输出GC的时间戳(以日期的形式,如 2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息

-Xloggc:../logs/gc.log 日志文件的输出路径

在我做了如下的设置

Java代码  收藏代码

  1. -XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps  

 

以后打印出来的日志为:

Java代码  收藏代码

  1. 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]  

  2. 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]  

  3. 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. 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. 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]  

  6. 7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]  

 

我们取倒数第二条记录分析一下各个字段都代表了什么含义

Java代码  收藏代码

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

 

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

从最后一条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 与预计的相符

 

重新设置GC日志的输出

 

Java代码  收藏代码

  1. -XX:+PrintGCDetails  

  2. -XX:+PrintHeapAtGC  

  3. -XX:+PrintGCDateStamps  

  4. -XX:+PrintTenuringDistribution  

  5. -verbose:gc  

  6. -Xloggc:gc.log  

后可以看到进行GC前后的堆内存信息 

Java代码  收藏代码

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

  2.  PSYoungGen      total 152896K, used 131072K [0x00000000f55600000x00000001000000000x0000000100000000)  

  3.   eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)  

  4.   from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)  

  5.   to   space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)  

  6.  PSOldGen        total 349568K, used 0K [0x00000000e00000000x00000000f55600000x00000000f5560000)  

  7.   object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)  

  8.  PSPermGen       total 26432K, used 26393K [0x00000000d00000000x00000000d19d00000x00000000e0000000)  

  9.   object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  

  10. 2013-05-05T23:16:10.480+08005.228: [GC  

  11. Desired survivor size 22347776 bytes, new threshold 7 (max 15)  

  12.  [PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]   

  13. Heap after GC invocations=1 (full 0):  

  14.  PSYoungGen      total 152896K, used 8319K [0x00000000f55600000x00000001000000000x0000000100000000)  

  15.   eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)  

  16.   from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)  

  17.   to   space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)  

  18.  PSOldGen        total 349568K, used 0K [0x00000000e00000000x00000000f55600000x00000000f5560000)  

  19.   object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)  

  20.  PSPermGen       total 26432K, used 26393K [0x00000000d00000000x00000000d19d00000x00000000e0000000)  

  21.   object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)  

  22. }  

 

Java代码  收藏代码

  1. [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)  

这种形式的日志有两种意义: 
当这种日志出现在generation的详细信息里的时候,三个数字在HotSpot里分别称为low_boundary、high、high_boundary。 
low_boundary: reserved space的最低地址边界;通常也跟“low”相等,这是commited space的最低地址边界 
high: commited space的最高地址边界 
high_boundary: reserved space的最高地址边界。 

[low_boundary, high_boundary)范围内的就是reserved space,这个space的大小就是max capacity。 
[low, high)范围内的就是commited space,而这个space的大小就是current capacity(当前容量),简称capacity。 
capacity有可能在一对最小值和最大值之间浮动。最大值就是上面说的max capacity。

本系列的最后一部分是有关垃圾收集(GC)日志的JVM参数。GC日志是一个很重要的工具,它准确记录了每一次的GC的执行时间和执行结果,通过分析GC日志可以优化堆设置和GC设置,或者改进应用程序的对象分配模式。

-XX:+PrintGC

参数-XX:+PrintGC(或者-verbose:gc)开启了简单GC日志模式,为每一次新生代(young generation)的GC和每一次的Full GC打印一行信息。下面举例说明:

1 [GC 246656K->243120K(376320K), 0.0929090 secs]
2 [Full GC 243120K->241951K(629760K), 1.5589690 secs]

每行开始首先是GC的类型(可以是“GC”或者“Full GC”),然后是在GC之前和GC之后已使用的堆空间,再然后是当前的堆容量,最后是GC持续的时间(以秒计)。

第一行的意思就是GC将已使用的堆空间从246656K减少到243120K,当前的堆容量(译者注:GC发生时)是376320K,GC持续的时间是0.0929090秒。

简单模式的GC日志格式是与GC算法无关的,日志也没有提供太多的信息。在上面的例子中,我们甚至无法从日志中判断是否GC将一些对象从young generation移到了old generation。所以详细模式的GC日志更有用一些。

-XX:PrintGCDetails

如果不是使用-XX:+PrintGC,而是-XX:PrintGCDetails,就开启了详细GC日志模式。在这种模式下,日志格式和所使用的
GC算法有关。我们首先看一下使用Throughput垃圾收集器在young
generation中生成的日志。为了便于阅读这里将一行日志分为多行并使用缩进。

1 [GC
2     [PSYoungGen: 142816K->10752K(142848K)] 246648K->243136K(375296K), 0.0935090 secs
3 ]
4 [Times: user=0.55 sys=0.10, real=0.09 secs]

我们可以很容易发现:这是一次在young
generation中的GC,它将已使用的堆空间从246648K减少到了243136K,用时0.0935090秒。此外我们还可以得到更多的信息:
所使用的垃圾收集器(即PSYoungGen)、young
generation的大小和使用情况(在这个例子中“PSYoungGen”垃圾收集器将young
generation所使用的堆空间从142816K减少到10752K)。

既然我们已经知道了young generation的大小,所以很容易判定发生了GC,因为young
generation无法分配更多的对象空间:已经使用了142848K中的142816K。我们可以进一步得出结论,多数从young
generation移除的对象仍然在堆空间中,只是被移到了old generation:通过对比绿色的和蓝色的部分可以发现即使young
generation几乎被完全清空(从142816K减少到10752K),但是所占用的堆空间仍然基本相同(从246648K到243136K)。

详细日志的“Times”部分包含了GC所使用的CPU时间信息,分别为操作系统的用户空间和系统空间所使用的时间。同时,它显示了GC运行的“真
实”时间(0.09秒是0.0929090秒的近似值)。如果CPU时间(译者注:0.55秒+0.10秒)明显多于”真实“时间(译者注:0.09
秒),我们可以得出结论:GC使用了多线程运行。这样的话CPU时间就是所有GC线程所花费的CPU时间的总和。实际上我们的例子中的垃圾收集器使用了8
个线程。

接下来看一下Full GC的输出日志

1 [Full GC
2     [PSYoungGen: 10752K->9707K(142848K)]
3     [ParOldGen: 232384K->232244K(485888K)] 243136K->241951K(628736K)
4     [PSPermGen: 3162K->3161K(21504K)], 1.5265450 secs
5 ]

除了关于young generation的详细信息,日志也提供了old generation和permanent
generation的详细信息。对于这三个generations,一样也可以看到所使用的垃圾收集器、堆空间的大小、GC前后的堆使用情况。需要注意
的是显示堆空间的大小等于young generation和old
generation各自堆空间的和。以上面为例,堆空间总共占用了241951K,其中9707K在young
generation,232244K在old generation。Full
GC持续了大约1.53秒,用户空间的CPU执行时间为10.96秒,说明GC使用了多线程(和之前一样8个线程)。

对不同generation详细的日志可以让我们分析GC的原因,如果某个generation的日志显示在GC之前,堆空间几乎被占满,那么很有
可能就是这个generation触发了GC。但是在上面的例子中,三个generation中的任何一个都不是这样的,在这种情况下是什么原因触发了
GC呢。对于Throughput垃圾收集器,在某一个generation被过度使用之前,GC
ergonomics(参考本系列第6节)决定要启动GC。

Full GC也可以通过显式的请求而触发,可以是通过应用程序,或者是一个外部的JVM接口。这样触发的GC可以很容易在日志里分辨出来,因为输出的日志是以“Full GC(System)”开头的,而不是“Full GC”。

对于Serial垃圾收集器,详细的GC日志和Throughput垃圾收集器是非常相似的。唯一的区别是不同的generation日志可能使用
了不同的GC算法(例如:old
generation的日志可能以Tenured开头,而不是ParOldGen)。使用垃圾收集器作为一行日志的开头可以方便我们从日志就判断出JVM
的GC设置。

对于CMS垃圾收集器,young generation的详细日志也和Throughput垃圾收集器非常相似,但是old
generation的日志却不是这样。对于CMS垃圾收集器,在old
generation中的GC是在不同的时间片内与应用程序同时运行的。GC日志自然也和Full
GC的日志不同。而且在不同时间片的日志夹杂着在此期间young
generation的GC日志。但是了解了上面介绍的GC日志的基本元素,也不难理解在不同时间片内的日志。只是在解释GC运行时间时要特别注意,由于
大多数时间片内的GC都是和应用程序同时运行的,所以和那种独占式的GC相比,GC的持续时间更长一些并不说明一定有问题。

正如我们在第7节中所了解的,即使CMS垃圾收集器没有完成一个CMS周期,Full GC也可能会发生。如果发生了GC,在日志中会包含触发Full GC的原因,例如众所周知的”concurrent mode failure“。

为了避免过于冗长,我这里就不详细说明CMS垃圾收集器的日志了。另外,CMS垃圾收集器的作者做了详细的说明(在这里),强烈建议阅读。

-XX:+PrintGCTimeStamps和-XX:+PrintGCDateStamps

使用-XX:+PrintGCTimeStamps可以将时间和日期也加到GC日志中。表示自JVM启动至今的时间戳会被添加到每一行中。例子如下:

1 0.185: [GC 66048K->53077K(251392K), 0.0977580 secs]
2 0.323: [GC 119125K->114661K(317440K), 0.1448850 secs]
3 0.603: [GC 246757K->243133K(375296K), 0.2860800 secs]

如果指定了-XX:+PrintGCDateStamps,每一行就添加上了绝对的日期和时间。

1 2014-01-03T12:08:38.102-0100: [GC 66048K->53077K(251392K), 0.0959470 secs]
2 2014-01-03T12:08:38.239-0100: [GC 119125K->114661K(317440K), 0.1421720 secs]
3 2014-01-03T12:08:38.513-0100: [GC 246757K->243133K(375296K), 0.2761000 secs]

如果需要也可以同时使用两个参数。推荐同时使用这两个参数,因为这样在关联不同来源的GC日志时很有帮助。

-Xloggc

缺省的GC日志时输出到终端的,使用-Xloggc:也可以输出到指定的文件。需要注意这个参数隐式的设置了参数-XX:+PrintGC和-XX:+PrintGCTimeStamps,但为了以防在新版本的JVM中有任何变化,我仍建议显示的设置这些参数。

可管理的JVM参数

一个常常被讨论的问题是在生产环境中GC日志是否应该开启。因为它所产生的开销通常都非常有限,因此我的答案是需要开启。但并不一定在启动JVM时就必须指定GC日志参数。

HotSpot JVM有一类特别的参数叫做可管理的参数。对于这些参数,可以在运行时修改他们的值。我们这里所讨论的所有参数以及以“PrintGC”开头的参数都是可管理的参数。这样在任何时候我们都可以开启或是关闭GC日志。比如我们可以使用JDK自带的jinfo工具来设置这些参数,或者是通过JMX客户端调用HotSpotDiagnostic MXBean的setVMOption方法来设置这些参数。

转载请注明:学时网 » GC日志分析

喜欢 (0)or分享 (0)

您必须 登录 才能发表评论!