JVM面试与调优(10)-GC日志案例分析

ゝ一纸荒年。 2022-08-29 10:11 190阅读 0赞

欢迎关注公众号「程猿薇茑」

![20191130143507670.jpg][]

### 文章目录 ###

*   *  GC日志案例分析
     *   *  GC分类
         *  GC日志分类
         *   *  MinorGC/Young GC
             *  FullGC
         *  GC日志结构
         *  Minor GC 日志案例分析
         *   *  开启GC日志
             *  分析GC日志
         *  Full GC 日志案例分析
     *  内存泄漏场景与案例

## GC日志案例分析 ##

### GC分类 ###

在Hotspot VM中，GC按照回收的区域分为两类。一类是部分收集（Partial GC），一种是整堆收集（Full GC）。

*  部分收集(Partial GC)
    
    不是完整地收集整个Java堆，这其中又分为
    
     *  新生代收集（ Minor GC /Young GC）：只是对新生代（Eden/S0、S1）的垃圾回收
     *  老年代收集（ Major GC /Old GC）：只是对老年代进行回收。目前只有CMS垃圾收集器才有单独收集老年代的行为；
     *  混合收集（Mixed GC）:收集整个新生代以及部分老年代。目前只有G1收集器才会有这种行为。
 *  整堆收集(Full GC)
    
    收集整个Java堆以及方法区。有的时候Major GC也被当做是Full GC，因此当有人说Major GC时要讲清楚到底是指老年代回收还是整堆回收。

各种收集之间的关系

1）新生代收集：当Eden区满的时候就会进行新生代收集，新生代收集和S0区域和S1区域占用情况无关。

2）老年代收集和新生代收集的关系：进行老年代收集之前会先进行一次年轻代的垃圾收集。一个比较大的对象无法放入新生代，那它会往老年代去放；如果老年代也放不下，那会先进行一次新生代的垃圾收集，之后尝试往新生代放，如果还是放不下，才会进行老年代的垃圾收集，之后再往老年代去放；之所以老年代放不下，要先对新生代进行垃圾回收，是因为新生代垃圾收集比老年代垃圾收集更加简单，这样做可以节省性能。

3）触发Full GC的情况：老年代空间不足；方法区空间不足；显示调用System.gc()；Minior GC进入老年代的数据的平均大小大于老年代的可用内存；大对象直接进入老年代，而老年代的可用空间不足。

### GC日志分类 ###

#### MinorGC/Young GC ####

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3pwY2FuZHpoag_size_16_color_FFFFFF_t_70_pic_center]

#### FullGC ####

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3pwY2FuZHpoag_size_16_color_FFFFFF_t_70_pic_center 1]

### GC日志结构 ###

GC日志结构主要分为3大块。

1）垃圾收集器标识

不同的垃圾收集器在GC日志中显示的名字不一样，换句话说，从GC日志输出的标识我们也可以断定该系统使用的是什么类型的收集器。下面列举一些常见的垃圾收集器在GC日志中的名字。

Serial收集器在新生代的名称是Default New Generation，GC日志显示的是"\[DefNew"

ParNew 收集器在新生代的名称是Parallel New Generation，GC日志显示的是"\[ParNew"

Parallel Scavenge收集器在新生代的名称是PSYoungGen，GC日志显示的就是"PSYoungGen"

Parallel Old Generation收集器在老年代的名称是"\[ParOldGen\]，GC日志显示的就是"\[ParOldGen\]"

G1收集器，日志显示"garbage-first heap"

GC日志中Allocation Failure表示的是触发本次GC的原因是年轻代中没有足够的空间存储新的数据了。

2）GC前后的空间占用情况

从上面的GC日志图示中，我们可以发现GC日志的格式一般都是：GC前内存占用->GC后内存占用(该区域总大小)

`[PSYoungGen:6852K->562K(8652K)] 6852K->598K(9852K)`

本例中，中括号内：GC前年轻代大小->回收后大小(年轻代总的空间大小)

中括号外：GC前年轻代和老年代大小->回收后大小(年轻代+老年代的总大小)

3）GC时间

GC日志中有3个时间：user、sys、real

user：进程执行用户态代码（内核态之外）所用的时间。这个时间是执行此进程所使用的实际CPU时间。其它进程和此进程阻塞的时间不包含在内。在垃圾回收的情况下，表示GC线程执行所使用的总的CPU时间。

sys：进程在内核态所消耗的CPU时间，在内核状态执行系统调用，或者等待系统事件所消耗的CPU时间。

real：程序从开始到结束所用的时间，此时间包括其它进程使用的时间片和进程阻塞时间(比如I/O等待)。在垃圾回收情况下，这个时间约等于 `(用户时间+系统时间)/垃圾收集器使用的线程数`

一般在多核CPU中，GC时的`real time<sys+user time`，因为一般会有多个线程执行GC。如果发现`real time>sys+user time`则可能I/O负载较高，或者是CPU数量不够用。

### Minor GC 日志案例分析 ###

#### 开启GC日志 ####

运行之前的TestGC1.java案例程序。指定运行时JVM参数开启GC日志：

`-Xms300M -Xmx300M -XX:SurvivorRatio=8 -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintGCDetails`

也可以指定将gc日志输出到文件中：  
`-Xloggc:/path/logs/gc.log`

一般产线配置使用滚动gc日志的方式，并且设置OOM前生成堆dump文件：

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps  -Xloggc:/path/logs/gc-%t.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=50M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/path/logs/apperror.hprof

%t会给文件名添加时间戳后缀，格式是`yyyy-MM-dd_HH-mm-ss`

#### 分析GC日志 ####

由于`TestGC1.java`程序是个死循环，不断添加数据的过程中必然会经历年轻代的回收、老年代回收、OOM。

运行一段时间后，IDEA控制台输出下列GC日志：

2021-07-28T22:32:31.778+0800: 50.236: [GC (Allocation Failure) [PSYoungGen: 81312K->9608K(92160K)] 81312K->53664K(296960K), 0.0146515 secs] [Times: user=0.00 sys=0.06, real=0.01 secs] 
    
    2021-07-28T22:33:40.834+0800: 119.292: [GC (Allocation Failure) [PSYoungGen: 91528K->9640K(92160K)] 135584K->124361K(296960K), 0.0191290 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    
    2021-07-28T22:34:50.893+0800: 189.351: [GC (Allocation Failure) [PSYoungGen: 91405K->10216K(92160K)] 206126K->196155K(296960K), 0.0225512 secs] [Times: user=0.05 sys=0.05, real=0.02 secs] 
    
    2021-07-28T22:34:50.915+0800: 189.374: [Full GC (Ergonomics) [PSYoungGen: 10216K->0K(92160K)] [ParOldGen: 185938K->195768K(204800K)] 196155K->195768K(296960K), [Metaspace: 9046K->9046K(1058816K)], 0.0233058 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    
    2021-07-28T22:36:01.992+0800: 260.450: [Full GC (Ergonomics) [PSYoungGen: 81549K->63488K(92160K)] [ParOldGen: 195768K->204650K(204800K)] 277318K->268139K(296960K), [Metaspace: 9066K->9007K(1058816K)], 0.0592801 secs] [Times: user=0.14 sys=0.02, real=0.06 secs] 
    
    2021-07-28T22:36:17.059+0800: 275.517: [Full GC (Ergonomics) [PSYoungGen: 81175K->78849K(92160K)] [ParOldGen: 204650K->204650K(204800K)] 285826K->283499K(296960K), [Metaspace: 9011K->9011K(1058816K)], 0.0181274 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
    
    2021-07-28T22:36:18.363+0800: 276.821: [Full GC (Ergonomics) [PSYoungGen: 81920K->80897K(92160K)] [ParOldGen: 204650K->204650K(204800K)] 286570K->285547K(296960K), [Metaspace: 9014K->9014K(1058816K)], 0.0086580 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
    
    2021-07-28T22:36:19.078+0800: 277.536: [Full GC (Ergonomics) [PSYoungGen: 81147K->80897K(92160K)] [ParOldGen: 204650K->204650K(204800K)] 285797K->285547K(296960K), [Metaspace: 9015K->9015K(1058816K)], 0.0083308 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
    
    2021-07-28T22:36:19.086+0800: 277.544: [Full GC (Allocation Failure) [PSYoungGen: 80897K->80897K(92160K)] [ParOldGen: 204650K->204615K(204800K)] 285547K->285512K(296960K), [Metaspace: 9015K->8939K(1058816K)], 0.0244277 secs] [Times: user=0.06 sys=0.00, real=0.03 secs]

我们看第一行日志，`2021-07-28T22:32:31.778+0800`是日志打印时间。`50.236`是gc发生时，Java虚拟机启动以来经过的秒数。

`GC (Allocation Failure)`表示发生了一次垃圾回收行为，且是一次Minior GC。括号里的内容表明了gc发生的原因，这里的Allocation Failure的原因是新生代中没有足够区域能够存放需要分配的数据而引发的失败。

`[PSYoungGen: 81312K->9608K(92160K)]`，`PSYoungGen`表示GC发生的区域是年轻代，区域名称与使用的GC收集器是密切相关的。具体的映射关系参考前文介绍的**垃圾收集器标识**。本案例中由于没有手动指定GC收集器，使用的是JDK8默认的垃圾收集器，即Parallel Scavenge（新生代）+Parallel Old（老年代）。从JDK9开始默认的垃圾收集器就是G1了。

`81312K->9608K(92160K)`表示GC前该内存区域已使用容量是81312K，GC后该区域使用容量为9608K，该区域总容量为92160K。

注意：如果是新生代，总容量则会显示整个新生代内存的9/10，即eden+from/to区。from和to中的一个相当于是备份的角色。

如果是老年代，总容量则是全部内存大小。

`81312K->53664K(296960K)`表示整个堆内存区域的GC情况。GC前整个堆内存已使用容量为`81312K`，GC后为`53664K`，整个堆内存的总容量为`296960K`。细心的读者会发现`296960K<300M`，这就是由于`堆内存总容量 = 9/10 新生代 + 老年代`，因此堆内存总容量肯定小于我们设置的初始化内存大小。我们设置的最大内存和初始内存是300M，新生代老年代的比例是1:2，因此新生代是100M，9/10 就是90M，因此`9/10 新生代 + 老年代=290M`，就是296960K。

`0.0146515 secs`表示整个GC所花费的时间，单位是秒。

`[Times: user=0.00 sys=0.06, real=0.01 secs]`表示指CPU工作在用户态所花费的时间、工作在内核态所花费的时间、在此次GC事件中所花费的总时间，单位为秒。

### Full GC 日志案例分析 ###

还是基于上面的GC日志，我们再来分析一下Full GC日志。我们看第四行日志，也就是第一次Full GC的日志。

`2021-07-28T22:34:50.915+0800`是日志打印时间，`189.374`是本次gc发生时，Java虚拟机启动以来经过的秒数。

`Full GC (Ergonomics)`，括号中的`Ergonomics`是gc发生的原因，`Ergonomics`表示是JVM自适应调整导致的GC。

括号中还有可能是下列选项：

`Full GC (System.gc())`：调用了System.gc()方法导致的gc。比如我们手动触发GC按钮；Java程序中调用System.gc()。

`Full GC (Metadata GCThreshold)`：Metaspace区不够用了导致的GC。

`[PSYoungGen: 10216K->0K(92160K)]`PSYoungGen表示GC发生的区域，这里就是年轻代。区域名称与使用的GC收集器是密切相关的，前文已经介绍过了。`10216K->0K(92160K)`表示GC前该内存区域已使用容量是10216K，GC后是0，即清空了。`92160K`表示该区域的总容量为90M。

`[ParOldGen: 185938K->195768K(204800K)]`表示老年代发生GC，GC前已使用容量185938K，GC后195768K，相当于没有回收成功。`204800K`表示老年代总的容量是200M。

`196155K->195768K(296960K)`表示的是整个堆内存区域的GC情况。GC前堆内存已使用容量为196155K，GC后堆内存已使用容量为195768K，整个堆内存总容量为296960K，即290M。

`[Metaspace: 9046K->9046K(1058816K)], 0.0233058 secs]`表示Meatspace的GC情况。JDK8开始叫Meatspace，之前的版本也叫做永久代，比如PSPermGen。`9046K->9046K(1058816K)`表示此次GC，Meatspace没有可回收的空间，回收前后占用空间没有变化，都是9046K。Meatspace的总的容量是1058816K，约等于1G。

`0.0233058 secs`表示整个GC所花费的时间，单位是秒。

`[Times: user=0.06 sys=0.00, real=0.02 secs]`和之前介绍的一致，不在赘述。

## 内存泄漏场景与案例 ##

所谓内存泄漏，一般是指对象不再需要使用了，但是垃圾收集器却不能回收它们，这就发生了内存泄漏。(一个不再会用到的对象占着内存空间，并且还不能释放)。比如，之前我们举的`MemoryLeak.java`案例。

有一些对象生命周期较长的场景也可能出现内存泄漏。比如对象A引用了对象B，A的生命周期比B 的长，B生命周期结束时，A依然引用着B。此时垃圾回收是不会回收B的。如果对象A还引用着其他的生命周期比较短的对象，那么就可能造成大量无用的对象不能被回收，进而占用大量内存空间，最终可能导致OOM。这也是内存泄漏的一种表现。

**内存泄漏和OOM的关系**：随着内存泄漏的增多，最终会导致内存溢出。

详情参考下一篇[《内存泄漏场景&线上JVM问题定位》][JVM]

[20191130143507670.jpg]: /images/20220829/af235a14592c4d899b5cde04c0c7d45d.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3pwY2FuZHpoag_size_16_color_FFFFFF_t_70_pic_center]: /images/20220829/8fe28f17d22d4f3f8f11a3716e412cb2.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3pwY2FuZHpoag_size_16_color_FFFFFF_t_70_pic_center 1]: /images/20220829/27fb0c0cb6d041c58d48cb9b5cbc0f8c.png
[JVM]: https://bigbird.blog.csdn.net/article/details/119305806