当前位置：首页 > news >正文

B02、分析GC日志-6.3

news 文章来源：https://blog.csdn.net/qq_37165235/article/details/137455168 2024/11/6 7:12:17

1、相关GC日志参数

-verbose:gc 输出gc日志信息，默认输出到标准输出
-XX:+PrintGC 输出GC日志。类似：-verbose:gc
-XX:+PrintGCDetails 在发生垃圾回收时打印内存回收详细的日志，
并在进程退出时输出当前内存各区域分配情况
-XX:+PrintGCTimeStamps 输出GC发生时的时间戳
-XX:+PrintGCDateStamps 输出GC发生时的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 每一次GC前和GC后，都打印堆信息
-Xloggc:<file> 表示把GC日志写入到一个文件中去，而不是打印到标准输出中

2、GC日志格式

2.1、GC 日志分类

2.1.1、Minor GC

Minor GC又叫oung GC或YGC，完整的输出日志：

[GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

根据上图解析示意图可得知以下规律：

2.1.2、Full GC

[GC (Allocation Failure) [PSYoungGen: 31744K->2192K(36864K)] 31744K->2200K(121856K), 0.0139308 secs] [Times: user=0.05 sys=0.01, real=0.01 secs]

2.1.3、补充说明

"[GC" 和 "[Full GC" 说明了这次垃圾收集的停顿类型，如果有 "Full" 则说明 GC 发生了 "Stop The World"
使用 Serial 收集器在新生代的名字是 Default New Generation，因此显示的是 "[DefNew"
使用 ParNew 收集器在新生代的名字会变成 "[ParNew"，意思是 "Parallel New Generation"
使用 Parallel scavenge 收集器在新生代的名字是 "[PSYoungGen"
使用Parallel Old Generation收集器在老年代的名字是 "[ParOldGen"
使用G1收集器的话，会显示为 "garbage-first heap"

Allocation Failure：表明本次引起GC的原因是因为在年轻代中没有足够的空间能够存储新的数据了。

2.2、GC日志结构

2.2.1、GC 前后情况

通过图示，我们可以发现GC日志格式的规律一般都是：GC前内存占用—>GC后内存占用（该区域内存总大小）：

[PSYoungGen: 5986K->696K(8704K)] 5986K->704K(9216K)

中括号内：GC回收前年轻代堆大小，回收后大小，（年轻代堆总大小）
括号外：GC回收前年轻代和老年代大小，回收后大小，（年轻代和老年代总大小）

2.2.3、GC 时间

GC日志中有三个时间：user，sys和real

user – 进程执行用户态代码（核心之外）所使用的时间。这是执行此进程所使用的实际 CPU 时间，其他进程和此进程阻塞的时间并不包括在内。在垃圾收集的情况下，表示 GC 线程执行所使用的 CPU 总时间。
sys – 进程在内核态消耗的 CPU 时间，即在内核执行系统调用或等待系统事件所使用的 CPU 时间
real – 程序从开始到结束所用的时钟时间。这个时间包括其他进程使用的时间片和进程阻塞的时间（比如等待 I/O 完成）。对于并行gc，这个数字应该接近（用户时间+系统时间）除以垃圾收集器使用的线程数。

由于多核的原因，一般的GC事件中，real time是小于sys + user time的，因为一般是多个线程并发的去做GC，所以real time是要小于sys+user time的。如果real>sys+user的话，则你的应用可能存在下列问题：IO负载非常重或者是CPU不够用。

2.3、Minor GC 日志解析

2023-11-20T17:19:43.265-0800: 0.822: [GC (ALLOCATION FAILURE) [PSYOUNGGEN: 76800K->8433K(89600K)] 76800K->8449K(294400K), 0.0088371 SECS] [TIMES: USER=0.02 SYS=0.01, REAL=0.01 SECS]

（2023-11-20T17:19:43.265-0800）：日志打印时间日期格式如 2024-05-04T21:53:59.234+0800
（0.822:）：gc发生时，Java虚拟机启动以来经过的秒数
（[GC (Allocation Failure)）：发生了一次垃圾回收，这是一次 Minor GC 。它不区分新生代 GC 还是老年代 GC，括号里的内容是gc发生的原因，这里的 Allocation Failure 的原因是新生代中没有足够区域能够存放需要分配的数据而失败。
（[PSYoungGen: 76800K->8433K(89600K)]）：
- PSYoungGen：表示GC发生的区域，区域名称与使用的GC 收集器是密切相关的
  - Serial收集器：Default New Generation 显示DefNew
  - ParNew收集器：ParNew
  - Parallel Scanvenge收集器： PSYoung
  - 老年代和新生代同理，也是和收集器名称相关
- 76800K->8433K(89600K)：GC 前该内存区域已使用容量 - > GC 后该区域容量（该区域总容量）
  - 如果是新生代，总容量则会显示整个新生代内存的9/10，即 eden+from/to 区
  - 如果是老年代，总容量则是全部内存大小，无变化
（76800K->8449K(294400K)）：在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC 前堆内存已使用容量 - > GC 堆内存容量（堆内存总容量），堆内存总容量 = 9/10 新生代+ 老年代 < 初始化的内存大小
（, 0.0088371 secs]）：整个GC所花费的时间，单位是秒
（[Times: user=0.02 sys=0.01, real=0.01 secs]）：
- user：指的是CPU工作在用户态所花费的时间
- sys：指的是CPU工作在内核态所花费的时间
- real：指的是在此次GC事件中所花费的总时间

2.4、Full GC 日志解析

2023-11-20T17:19:43.794-0800: 1.351: [FULL GC (METADATA GC THRESHOLD) [PSYOUNGGEN: 10082K->0K(89600K)] [PAROLDGEN: 32K->9638K(204800K)] 10114K->9638K(294400K),
[METASPACE: 20158K->20156K(1067008K)], 0.0285388 SECS] [TIMES: USER=0.11 SYS=0.00, REAL=0.03 SECS]

（2023-11-20T17:19:43.794-0800）：日志打印时间日期格式如 2013-05-04T21:53:59.234+0800
（1.351）：gc发生时，Java虚拟机启动以来经过的秒数
（Full GC (Metadata GC Threshold)）：
- 发生了一次垃圾回收，这是一次FULL GC 。它不区分新生代 GC 还是老年代 GC
- 括号里的内容是gc发生的原因，这里的 Metadata GC Threshold 的原因是 Metaspace 区不够用了。
  - Full GC (Ergonomics) ：JVM 自适应调整导致的GC
  - Full GC (System）：调用了System.gc( ) 方法
（[PSYoungGen: 10082K->0K(89600K)]）：
- PSYoungGen：表示GC发生的区域，区域名称与使用的GC 收集器是密切相关的
  - Serial收集器：Default New Generation 显示DefNew
  - ParNew收集器：ParNew
  - Parallel Scanvenge收集器： PSYoung
  - 老年代和新生代同理，也是和收集器名称相关
- 10082K->0K(89600K)：GC 前该内存区域已使用容量 - > GC 后该区域容量（该区域总容量）
  - 如果是新生代，总容量则会显示整个新生代内存的9/10，即 eden+from/to 区
  - 如果是老年代，总容量则是全部内存大小，无变化
（[ParOldGen: 32K->9638K(204800K)]）：老年代区域没有发生GC，因为本次GC是metaspace 引起的
（10114K->9638K(294400K),）：在显示完区域容量GC的情况之后，会接着显示整个堆内存区域的GC情况：GC 前堆内存已使用容量 - > GC 堆内存容量（堆内存总容量）堆内存总容量 = 9/10 新生代+ 老年代 < 初始化的内存大小
（[Metaspace: 20158K->20156K(1067008K)],）：metaspace GC 回收2K空间
（0.0285388 secs）：整个GC所花费的时间，单位是秒
（[Times: user=0.11 sys=0.00, real=0.03 secs]）：
- user：指的是CPU工作在用户态所花费的时间
- sys：指的是CPU工作在内核态所花费的时间
- real：指的是在此次GC事件中所花费的总时间

3、案例演示

3.1、代码示例

package blnp.net.cn.jvm.demos;/**** 在jdk7 和 jdk8中分别执行*  -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC** @author lyb 2045165565@qq.com* @createDate 2024/4/7 14:49*/
public class GcLogTest {private static final int _1MB = 1024 * 1024;public static void testAllocation() {byte[] allocation1, allocation2, allocation3, allocation4;allocation1 = new byte[2 * _1MB];allocation2 = new byte[2 * _1MB];allocation3 = new byte[2 * _1MB];allocation4 = new byte[4 * _1MB];}public static void main(String[] agrs) {testAllocation();}}

JDK1.7.0_080版本的执行结果：

Connected to the target VM, address: '127.0.0.1:56576', transport: 'socket'
[GC[DefNew: 8174K->618K(9216K), 0.0050449 secs] 8174K->6762K(19456K), 0.0051236 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
Heapdef new generation   total 9216K, used 4879K [0x00000000f9a00000, 0x00000000fa400000, 0x00000000fa400000)eden space 8192K,  52% used [0x00000000f9a00000, 0x00000000f9e296c0, 0x00000000fa200000)from space 1024K,  60% used [0x00000000fa300000, 0x00000000fa39a900, 0x00000000fa400000)to   space 1024K,   0% used [0x00000000fa200000, 0x00000000fa200000, 0x00000000fa300000)tenured generation   total 10240K, used 6144K [0x00000000fa400000, 0x00000000fae00000, 0x00000000fae00000)the space 10240K,  60% used [0x00000000fa400000, 0x00000000faa00030, 0x00000000faa00200, 0x00000000fae00000)compacting perm gen  total 21248K, used 3049K [0x00000000fae00000, 0x00000000fc2c0000, 0x0000000100000000)the space 21248K,  14% used [0x00000000fae00000, 0x00000000fb0fa698, 0x00000000fb0fa800, 0x00000000fc2c0000)
No shared spaces configured.
Disconnected from the target VM, address: '127.0.0.1:56576', transport: 'socket'

JDK1.8.0_321版本的执行结果：

Connected to the target VM, address: '127.0.0.1:49940', transport: 'socket'
[GC (Allocation Failure) [DefNew: 6517K->676K(9216K), 0.0024239 secs] 6517K->4772K(19456K), 0.0024547 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heapdef new generation   total 9216K, used 7224K [0x00000000fec00000, 0x00000000ff600000, 0x00000000ff600000)eden space 8192K,  79% used [0x00000000fec00000, 0x00000000ff264f08, 0x00000000ff400000)from space 1024K,  66% used [0x00000000ff500000, 0x00000000ff5a9320, 0x00000000ff600000)to   space 1024K,   0% used [0x00000000ff400000, 0x00000000ff400000, 0x00000000ff500000)tenured generation   total 10240K, used 4096K [0x00000000ff600000, 0x0000000100000000, 0x0000000100000000)the space 10240K,  40% used [0x00000000ff600000, 0x00000000ffa00020, 0x00000000ffa00200, 0x0000000100000000)Metaspace       used 3100K, capacity 4556K, committed 4864K, reserved 1056768Kclass space    used 327K, capacity 392K, committed 512K, reserved 1048576K
Disconnected from the target VM, address: '127.0.0.1:49940', transport: 'socket'

3.2、图解过程

JDK1.7

JDK1.8

4、GC日志分析工具

4.1、GCeasy

官网地址，GCeasy是一款在线的GC日志分析器，可以通过GC日志分析进行内存泄漏检测、GC暂停原因分析、JVM配置建议优化等功能，而且是可以免费使用的（有一些服务是收费的）。

注意：该站点国内访问较不稳定，如果打开失败可以多刷新几次。

4.2、GCView

GCViewer是一个免费的、开源的分析小工具，用于可视化查看由SUN/Oracle,IBM,HP和BEA Java虚拟机产生的垃圾收集器的日志。

GCViewer用于可视化Java VM选项-verbose:gc 和.NET生成的数据-Xloggc:<file>。它还计算与垃圾回收相关的性能指标（吞吐量，累积的暂停，最长的暂停等）。当通过更改世代大小或设置初始堆大小来调整特定应用程序的垃圾回收时，此功能非常有用。

下载地址，只需双击gcviewer-1.3x.jar或运行java -jar gcviewer-1.3x.jar（它需要运行java 1.8 vm），即可启动GCViewer（gui）。

4.3、其它工具

4.3.1、HPjmeter

工具很强大，但只能打开由以下参数生成的GC log， -verbose:gc -Xloggc:gc.log。添加其他参数生成的gc.log无法打开。HPjmeter集成了以前的HPjtune功能，可以分析在HP机器上产生的垃圾回收日志文件。