jvm gc日志分析

野性酷女 2021-09-12 07:34 417阅读 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的前后打印出堆的信息  
\-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日志导入，然后可以看到下面的图

![Center][]

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

![Center 1][]

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

![Center 2][]

2）gchisto

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

3）GCLogViewer：

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

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

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

[Java]: http://lib.csdn.net/base/javase
[Center]: /images/20210511/6d6702f0cb634da8a8f24717c7bdec29.png
[Center 1]: /images/20210511/c672a48a858b4736b8275fd28802b0a7.png
[Center 2]: /images/20210511/d22d4f8b19764fb7bedfc0026faf05c3.png