jvm gc日志分析

原创

赶路人儿 2022-06-19 22:09:32 博主文章分类：java ©著作权

文章标签 jvm gc 内存空间 sed 老年代 文章分类 Java 后端开发

©著作权归作者所有：来自51CTO博客作者赶路人儿的原创作品，请联系作者获取转载授权，否则将追究法律责任

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://www.importnew.com/19593.html

4、常用的gc工具：

1）gcview：

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

这个地址是网上找的，可以支持jdk更高版本

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

jvm gc日志分析_老年代

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

jvm gc日志分析_sed_02