GC日志详解

无涯WuYa

发布于 2023-02-28 15:55:38

7000

发布于 2023-02-28 15:55:38

JVM的内存结构从大的结构来说主要分为堆区和非堆区。在实际测试中针对IO密集型的程序往往需要它的高可用，也就是在客户端高并发以及持续不断的向服务发送请求进行交互的时候，是否存在堆区或者是非堆区的内存泄露。如针对发送短信服务而言能够处理的最大短信量是100万，那么当N个100万的任务同时发送请求以及大于100万的任务发送请求，服务端极有可能存在内存泄露的情况，此时就需要打印以及输出GC的日志信息并且来关注分析GC的日志信息。下面详细地阐述下GC的日志信息。

GC日志打印

在程序中打印GC打印出日志信息，那么详细的阐述下打印GC日志需要使用到的命令信息，具体如下：

-XX:+PrintGCDetails  #打印GC的详细日志信息
-XX:+PrintGCTimeStamps #打印GC时间戳
-XX:+PrintGCDateStamps #打印GC开始GC开始时间
-Xloggc:$CATALINA_HOME/logs/gc.log - #gc日志输出到gc.log的文件里面
XX:+PrintHeapAtGC #发生GC的时候打印堆的使用情况
-XX:+PrintTenuringDistribution #发生GC的时候打印下新生代年龄的分区

下面演示下在程序中添加GC的日志信息。在IDEA的IDE中，在菜单栏的Run中点击Edit Configurations中，在弹出框的VM options中添加打印出GC的详细信息和GC的日志输出到日志文件里面，具体如下：

启动程序后就会打印出GC的日志信息，打印出的GC日志是基于ParallelGC的认日志格式，具体见如下的详细日志信息：

Java HotSpot(TM) 64-Bit Server VM (25.241-b07) for bsd-amd64 JRE (1.8.0_241-b07), built on Dec 11 2019 02:29:59 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 8388608k(54540k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=./ -XX:InitialHeapSize=33554432 -XX:+ManagementServer -XX:MaxHeapSize=33554432 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2022-12-25T20:57:24.289-0800: 0.391: [GC (Allocation Failure) [PSYoungGen: 8704K->1008K(9728K)] 8704K->1643K(31744K), 0.0023364 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2022-12-25T20:57:24.423-0800: 0.525: [GC (Allocation Failure) [PSYoungGen: 9712K->1012K(9728K)] 10347K->2965K(31744K), 0.0030215 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

如下详细的解读下GC的日志信息，具体详细信息如下：

2022-12-25T20:57:24.289-0800：表示的是一个日期格式
GC (Allocation Failure)：表示的是发生GC的原因
PSYoungGen：表示的是Young区
PSYoungGen: 8704K：垃圾回收之前的Young区大小
PSYoungGen: 8704K->1008K(9728K)：1008K指的是垃圾回收之后的Young区大小
PSYoungGen: 8704K->1008K(9728K)：9728K指的是Young区的总大小
8704K->1643K(31744K)：8704K是垃圾回收之前堆的大小,1643K是垃圾回收之后堆的大小,31744K是堆的总大小
0.0023364 secs：指的是垃圾回收所使用到的时间

2022-12-25T20:57:25.441-0800: 1.543: [Full GC (Metadata GC Threshold) [PSYoungGen: 560K->0K(8192K)] [ParOldGen: 11190K->8772K(22016K)] 11751K->8772K(30208K), [Metaspace: 20228K->20228K(1067008K)], 0.0287965 secs] [Times: user=0.12 sys=0.00, real=0.03 secs] 
Full GC的原因是Metaspace不够导致的Full GC。

如是针对GC日志的详解，GC日志比较庞大，分析起来不是特别的友好，所以下面详细的阐述下在线GC日志的分析和工具模式针对GC日志的分析，也就是通过可视化的模式来对GC日志分析会更加友好和高效。

gceasy在线分析

打开https://gceasy.io/ 网站后，加载GC的日志，就能够自动分析出GC的吞吐量以及相应时间和其他的信息，如下图信息所示：