JVM GC日志文件分析

客官°小女子只卖身不卖艺 2023-05-21 08:47 14阅读 0赞

# JVM GC日志文件分析 #

GC 是垃圾回收(Garbage Collection)的缩写。两个关键名词：**垃圾**、**回收**。**那何谓垃圾呢**，JVM认为没有任何引用指向的对象就是垃圾对象，JVM里面判定为垃圾的算法有：应用计数法、可达性分析法。**何谓回收呢**，回收就是把认为是垃圾对象的内存回收回来，JVM里面的回收算法有：标记-清除算法、复制算法、标记整理算法、分代收集算法。GC日志文件就是JAVA虚拟机产生的一种对垃圾回收情况描述性的日志文件。 通过阅读GC日志文件，我们可以了解JAVA虚拟机内存分配情况(因为垃圾回收的对象就是内存)和垃圾回收信息。

> GC的对象是内存，又因为内存是在JVM堆区分配的，换句话说GC的对象是JVM堆区(当然也包括方法区的内存)。

## 一 GC日志文件生成 ##

### 1.1 GC日志文件JVM相关参数 ###

<table> 
 <thead> 
  <tr> 
   <th>GC日志文件相关的选项</th> 
   <th>解释</th> 
  </tr> 
 </thead> 
 <tbody> 
  <tr> 
   <td>-XX:+PrintGC (或者-verbose:gc)</td> 
   <td>输出GC日志(可以认为-verbose:gc 是 -XX:+PrintGC的别名)</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCDetails</td> 
   <td>输出 GC 详细的日志, 包括 GC 使用的收集器, 发生 GC 的区域, GC 空间收集情况等信息，该参数会自动开启-XX:+PrintGC</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCTimeStamps</td> 
   <td>在输出 GC 日志的时候输出时间戳, 这个时间戳是相对于虚拟机的启动时间</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCDateStamps</td> 
   <td>在输出 GC 日志的时候输出 GC 发生的时间（以日期的形式，如2013-05-04T21:53:59.234+0800）</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintHeapAtGC</td> 
   <td>在发生 GC 时输出 GC 前后各区域空间详细的对比信息, 对 -XX:PrintGCDetails 更加详细的补充</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintReferenceGC</td> 
   <td>在 GC 的时候打印系统中的软引用, 弱引用和虚引用等引用的数量信息</td> 
  </tr> 
  <tr> 
   <td>-Xloggc</td> 
   <td>输出 GC 日志到文件, 方便排查问题, 如果不配置路径, GC 日志将直接在控制台输出,格式为，-Xloggc:/path/xxx.log，或者-Xloggc:/path/gc-%t.log</td> 
  </tr> 
  <tr> 
   <td>-XX:+UseGCLogFileRotation</td> 
   <td>是否启用 GC 日志文件自动转储, GC 日志文件按大小切割时需要设置</td> 
  </tr> 
  <tr> 
   <td>XX:GCLogFileSize</td> 
   <td>控制 GC 日志文件的大小, 用于 GC 日志的切割, 不宜设置太大, 太大由于写日志需要进行 I/O 操作, I/O 操作需要在用户态和和心态之间切换, 会直接影响 user time 大小和 sys time 大小, 最终影响到 real time 大小, real time 就是 GC 耗费的时间。例如：-XX:GCLogFileSize=50M</td> 
  </tr> 
  <tr> 
   <td>-XX:NumberOfGClogFiles</td> 
   <td>GC 日志文件最多保存的个数。例如：-XX:NumberOfGClogFiles=10</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCApplicationStopedTime</td> 
   <td>查看GC造成的应用暂停时间</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintTenuringDistribution</td> 
   <td>对象晋升的日志</td> 
  </tr> 
  <tr> 
   <td>-XX:+HeapDumpOnOutOfMemoryError</td> 
   <td>内存溢出时输出 dump 文件</td> 
  </tr> 
 </tbody> 
</table>

### 1.2 GC日志文件生成 ###

比如我们可以在我们的应用程序java -jar启动的时候添加如下参数，这样程序运行过程中会把GC日志文件输出到gclogs文件里面去。拿到GC日志文件之后，我们可以对gclogs文件做相应的分析。

-XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:./gclogs

## 二 GC日志文件分析 ##

### 2.1 GC日志文件解读 ###

当我们拿到GC日志文件之后，用文本方式打开文件可以看到一堆的文字和数据信息。其实里面的内容不复杂就是文件比较多而已。我们得先来介绍下GC日志文件格式，GC日志文件包含哪些内容，每个内容代表啥意思。在了解了日志文件格式之后我们才可以对GC日志文件做简单的分析。这里为了简单我就通过一个图来介绍GC日志文件里面每个区域所代表的意思。

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

> GC的原因：
> 
>  *  Allocation Failure：年轻代中没有足够的空间存储数据了。
>  *  Metadata GC Threshold：元空间没有足够的空间存储数据了。
>  *  Ergonomics：GC的原因是因为要自动调解GC暂停时间和吞吐量之间的平衡
>  *  System.gc()：GC的原因是因为调用了System.gc()函数

### 2.2 GC日志文件分析工具 ###

GC日志文件的内容信息，我们上面分析清楚了。接下来就是对GC日志文件做简单的分析了。为了节约咱们得分析时间。我们直接介绍一个非常好用GC日志文件在线分析工具gceasy。对应官网 https://gceasy.io/ 。打开网址，把我们生成的GC日志文件导入进去。就会以图形化的界面帮我们展示GC日志文件里面所有你需要的信息了。展示的信息简单直接明了。

#### 2.2.1 JVM memory size（JVM内存大小区域） ####

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

JVM memory size，gceasy给展示了年轻代，老年代，元空间。JVM给分配的大小和程序运行过程中实际使用的峰值大小。

从JVM memory size展示的信息，我们可以判断是否需要做如下几件事情：

*  是否需要修改JVM内存(-Xms、-Xmx…)相关设置。比如年轻代和老年代峰值大小远远小于分配的大小。这个时候我们可以适当的减少内存设置。
 *  是否需要调整年轻代和老年代的比例(-XX:NewSize(-Xns)、-XX:MaxNewSize(-Xmn)、-XX:SurvivorRatio=8)。比如老年代的峰值一直小于老年代申请的内存，这个时候我们就可以稍微多分点空间给年轻代；
 *  是否需要修改元空间(XX:MetaspaceSize，-XX:MaxMetaspaceSize)相关设置。

> 年轻代，老年代属于堆区。元空间属于非堆区(直接对接的是机器的内存)。

#### 2.2.2 Key Performance Indicators（关键性能指标） ####

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

Key Performance Indicators给我们展示了GC吞吐量(应用程序线程用时占程序总用时的比例，越高越好)、每次GC的平均耗时(建议控制在50毫秒以下)、GC最长耗时、每个时间段的GC次数等信息。

Key Performance Indicators显示的信息里面，我们得关注点应该在以下几个方面：

*  吞吐量，应用花在非GC上的时间百分比(引用花在生产任务上的百分比)。所以吞吐量越高越好。
 *  每次GC的平均耗时。越小越好，建议50毫秒一下。
 *  GC最长耗时。越小越好。如果你的应用是一个后台程序，并且任何请求不超过10秒。那么GC最长耗时就不能超过10秒。

根据内存调优准则，以上这三个优化指标，你最多只能三者取其二

*  如果你想要比较好的**吞吐量**和**延迟**，那就得在**CPU消耗**上有所牺牲
 *  如果你想要比较好的**吞吐量**和**CPU消耗**，那就得在**延迟**上有所牺牲
 *  如果你想要比较好的**延迟**和**CPU消耗**，那就得在**吞吐量**上有所牺牲

#### 2.2.3 Interactive Graphs(交互图) ####

Interactive Graphs展示了Heap after GC、Heap before GC、GC Duration、Reclaimed Bytes、Young Gen、Old Gen、Meta Space、A & P对应的信息。

*  Heap after GC: 每次GC后堆的内存信息。

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

*  Heap before GC: 每次GC前堆的内存信息。

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

*  GC Duration: 每次GC的持续时间。(注意红色的是Full GC)

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 5]  
OWIxZjk4ZjIxNDFjZjkucG5n?x-oss-process=image/format,png)

*  Reclaimed Bytes: 每次GC回收掉的垃圾对象的内存大小。

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

*  Young Gen: 三条曲线分别展示年轻代每次GC的时候JVM给年轻代分配的内存大小、GC前使用内存大小、GC后使用内存大小。

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

*  Old Gen: 三条曲线分别展示老年代每次GC的时候JVM给老年代分配的内存大小、GC前使用内存大小、GC后使用内存大小。

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

*  Meta Space: 三条曲线分别展示元空间每次GC的时候给分配的内存大小、GC前使用内存大小、GC后使用内存大小。

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

*  A & P: 每次GC的时候堆内存分配和晋升情况。其中红色的线表示每次GC的时候年轻代里面有多少内存(对象)晋升到了老年代。

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

#### 2.2.4 GC Statistics(GC统计信息) ####

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

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

GC Statistics显示一些GC的统计信息。每种GC总共回收了多少内存、总共用了多长时间、平均时间、以及每种GC的单独统计信息啥的。

#### 2.2.5 Object Stats(对象的一些统计信息) ####

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

#### 2.2.6 GC Causes(GC的原因信息) ####

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

--------------------

以上就是我们对GC日志文件的一个大致介绍，主要是介绍GC日志文件分析工具，为我们后续分析GC日志文件做准备。

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center]: /images/20230521/47c81ef1813c46fe8323059bde6ba1ff.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 1]: /images/20230521/8cc2f3def7fe4c64be6a5bbc56c8bd47.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 2]: /images/20230521/e9b67f08791f4d01b607d863bc74dac7.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 3]: /images/20230521/9dd2c2487b2042a78a3d36759f7f4fbc.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 4]: /images/20230521/0d271d991b0a41e3b377926b67a522be.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 5]: /images/20230521/94399b72aff441a09e550a2086c2d83f.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 6]: /images/20230521/1caf16dc62b74886bddfc923a177dabf.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 7]: /images/20230521/a79738b5662b415f8ae6d28696248feb.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 8]: /images/20230521/6f438ae0db1a4466b822a26e43f1ad01.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 9]: /images/20230521/6aca5fec08b042b3bf677dd3b5bf2b22.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 10]: /images/20230521/f5ead23d57bd44ada3e741bd649eb3a5.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 11]: /images/20230521/a9e003d6764d445b9cc653027e5dbbbc.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 12]: /images/20230521/2b7276d0d37e46388db115b05ac74fee.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 13]: /images/20230521/a80fb86c312143c8a96f55956cee564b.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3d1eXV4aW5nMjQ_size_16_color_FFFFFF_t_70_pic_center 14]: /images/20230521/764ccc26adff40db8f324465893313b1.png