【Java虚拟机】JVM日志分析和可视化工具实操-阿里云开发者社区

1.JVM垃圾GC日志参数配置实战

Java虚拟机中垃圾收集器在运行过程中输出的日志信息
主要用于分析垃圾收集器的运行状态、优化垃圾收集器的工作效率以及定位垃圾收集相关的问题
GC日志会包含以下内容
垃圾收集器的名称和版本信息。
垃圾收集器的运行时间、开始时间和结束时间。
垃圾收集器的运行模式、垃圾收集算法和垃圾收集器的参数设置。

垃圾收集器的运行情况，包括垃圾收集的次数、垃圾收集的时间、垃圾回收的内存空间等

常见参数

参数配置	说明

-XX:+PrintGC	简单GC日志，JDK8后过期，后续会被移除，新版采用 -Xlog:gc
-XX:+PrintGCDetails	GC详细日志，JDK8后过期，后续会被移除，新版采用-Xlog:gc*

-Xloggc:gc.log	输出GC日志到文件，可以指定绝对的路径，JDK8后过期，后续会被移除，新版采用-Xlog:gc:`file=<filepath>`
-verbose:gc	标准的选项，输出GC日志

测试代码

/**
 * 模拟OOM测试
 * @author lixiang
 * @date 2023/5/4 20:53
 */
public class JVMTest {
    public static void main(String[] args) throws InterruptedException {
        List<Object> objects = new ArrayList<>();
        while(true){
            objects.add(new Object());
        }
    }
}

配置案例实战，JDK11版本，G1垃圾收集器

-XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms524m -Xmx524m -XX:+PrintCommandLineFlags -Xlog:gc:gc.log

新版GC日志输出的组成部分

时间戳：记录GC发生的时间戳，精确到毫秒
日志级别：日志的级别，包括debug、trace、info、warning、error等
日志标签：日志的标签，用于区分不同类型的日志
日志内容：记录GC相关的信息，包括GC算法、GC的时间、GC前后的内存使用情况、回收的对象数量等。
新版GC日志配置格式 -Xlog:[selectors]:[output]:[decorators][:output-options]
JVM 采用的是 =的形式来表示 selectors
默认情况下 tag 为all，表示所有的 tag，level 为 INFO
selector 可以进行组合的，不同的 selector 之间用逗号分隔

同时输出 gc 和 gc+metaspace 这两类 tag 的日志 -Xlog:gc=debug,gc+metaspace:gc.log

-XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms524m -Xmx524m -XX:+PrintCommandLineFlags  -Xlog:gc=debug,gc+metaspace:gc.log

JVM 提供了通配符 * 来解决精确匹配的问题，比如想要所有 tag 为 gc 的debug级别日志 -Xlog:gc*=debug

-XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms524m -Xmx524m -XX:+PrintCommandLineFlags  -Xlog:gc*=debug:gc.log
# gc*=debug：指定输出GC相关日志，级别为debug，*表示所有的GC标签都会输出日志。

日志文件解读

-XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms524m -Xmx524m -XX:+PrintCommandLineFlags -Xlog:gc=info:gc.log

日志内容
[24.575s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 240M->238M(528M) 5.888ms
字段拆解
  [24.575s]：GC发生的时间戳，表示程序运行的时间
  [info]：日志级别，表示这是一条信息级别的日志
  [gc]：日志标签，表示这是一条GC相关的日志
  GC(0)：GC的编号，表示这是第一次GC
  Pause Young (Concurrent Start) (G1 Humongous Allocation)：
    GC的类型，表示这是一次Young GC，同时也是一次 Humongous Allocation的GC，其中Concurrent Start表示并发启动的GC。
  240M->238M(528M)：
    GC前后堆内存的使用情况，其中240M表示GC前的已使用内存，238M表示GC后的已使用内存，528M表示堆内存的总大小
  5.888ms：GC的耗时，表示这次GC的执行时间
  这条GC日志记录了程序运行了24.575秒时发生的一次Young GC，回收了2M的内存空间，耗时5.888毫秒
————————————————————————————————————————————————————————
日志内容
[24.783s][info][gc] GC(3) Concurrent Cycle
[24.784s][info][gc] GC(3) Pause Remark 242M->242M(528M) 0.383ms
[24.784s][info][gc] GC(3) Pause Cleanup 242M->242M(528M) 0.066ms
[24.785s][info][gc] GC(3) Concurrent Cycle 2.374ms
字段拆解
  [24.783s][info][gc] GC(3) Concurrent Cycle：
  Mixed GC的相关信息，表示这是一次Mixed GC的开始。
  [24.784s][info][gc] GC(3) Pause Remark 242M->242M(528M) 0.383ms
  Mixed GC的相关信息，表示这是一次Remark阶段的GC，回收了0M的内存空间，耗时0.383毫秒。
  [24.784s][info][gc] GC(3) Pause Cleanup 242M->242M(528M) 0.066ms：
  Mixed GC的相关信息，表示这是一次Cleanup阶段的GC，回收了0M的内存空间，耗时0.066毫秒。
  [24.785s][info][gc] GC(3) Concurrent Cycle 2.374ms：
  Mixed GC的相关信息，表示这是一次Mixed GC的结束，耗时2.374毫秒。
  这段GC日志记录了程序运行了24.783秒一次Mixed GC，Mixed GC回收了0M的内存空间，耗时2.374毫秒

使用技巧

GC日志输出到文件中 -Xlog:gc=info:file=/path/app.log
指定日志切割的大小和方式 -

Xlog:gc=info:file=/path/app.log:filesize=104857600,filecount=5

filesize=104857600：指定单个日志文件大小为100MB，超过这个大小会自动切换到新的日志文件。

filecount=5：指定日志文件数量不超过5个，超过这个数量会删除最早的日志文件。

配置实操

-XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms524m -Xmx524m -XX:+PrintCommandLineFlags -Xlog:gc*=info:file=portal_gc.log:utctime,level,tags:filecount=5,filesize=1M

详细解释字段

-XX:+UseG1GC：使用G1垃圾回收器
-XX:MaxGCPauseMillis=100：设置最大垃圾回收暂停时间为100毫秒
-Xms524m：设置JVM堆的初始大小为524MB
-Xmx524m：设置JVM堆的最大大小为524MB
-XX:+PrintCommandLineFlags：打印JVM启动参数
-Xlog:gc*=info:file=portal_gc.log:utctime,level,tags:filecount=5,filesize=1M：
  Xlog：指定日志输出方式为日志文件。
  gc*：指定日志输出类型为GC相关的日志。
  info：指定输出日志的级别为info级别。
  file=portal_gc.log：指定日志输出的文件名为portal_gc.log。
  utctime：指定日志输出的时间戳使用UTC时间。
  level,tags：指定日志输出的格式包含级别和标签信息。
  filecount=5：指定最多保存5个日志文件。
  filesize=1M：指定每个日志文件的大小为1MB。

该配置使用G1垃圾回收器，设置最大垃圾回收器暂停时间为100毫秒，JVM堆的初始堆大小和最大堆大小均为524MB，并打印JVM启动参数和输出GC日志到文件portal_gc.log中，文件数量为5个，每个文件大小为1MB，日志格式为info级别，包含时间戳、级别和标签。

2.JVM内存OOM堆栈快照配置实战

配置OOM时的堆栈快照信息

-XX:+HeapDumpOnOutOfMemoryError：当发生OOM时，自动生成堆栈快照文件。
-XX:HeapDumpPath= ：指定堆栈快照文件的输出路径。

-XX:OnOutOfMemoryError=“；”：当发生OOM时，执行指定的命令

案例-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=heapdump.hprof

-XX:+UseG1GC -XX:MaxGCPauseMillis=100 -Xms524m -Xmx524m -XX:+PrintCommandLineFlags -Xlog:gc*=info:file=portal_gc.log:utctime,level,tags:filecount=5,filesize=1M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=heapdump.hprof

将在发生OOM时生成一个名为heapdump.hprof的堆栈快照文件，并将其保存到当前项目的目录下
heapdump.hprof 文件可以使用多种工具进行分析

在线分析工具：https://heaphero.io

堆分析工具可能需要大量的内存和计算资源来加载和分析heapdump.hprof文件

建议在高配置的机器上运行堆分析工具，并为其分配足够的内存和计算资源

生产环境配置案例

服务器配置是8核16g内存，需要部署一个springboot写的电商项目，日访问量100万左右的UV

给一份生产环境配置的jvm参数的值，要求基于jdk11+配置oom时的堆栈快照信息

-server
-Xms8g
-Xmx8g
-XX:+UseG1GC
-XX:MaxGCPauseMillis=200
-XX:G1HeapRegionSize=32M
-XX:ActiveProcessorCount=8
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=heapdump.hprof
-XX:+PrintCommandLineFlags 
-Xlog:gc*=info:file=portal_gc.log:utctime,level,tags:filecount=50,filesize=100M
参数说明
  -Xms8g：指定JVM堆内存最小值为8G。
  -Xmx8g：指定JVM堆内存最大值为8G。
  -XX:+UseG1GC：指定使用G1垃圾收集器。
  -XX:MaxGCPauseMillis=200：指定最大垃圾回收暂停时间为200毫秒。
  -XX:G1HeapRegionSize=32M：指定G1垃圾收集器的堆区域大小为32MB。
  -XX:ActiveProcessorCount=8：指定并行垃圾回收器的线程数为8，在JDK 9及之后的版本中，ParallelGCThreads参数已被替代为-XX:ActiveProcessorCount参数，用于自动计算并行垃圾回收线程数
  -server：指定JVM使用服务器模式运行，优化性能。
  -XX:+HeapDumpOnOutOfMemoryError：指定在发生内存溢出时生成堆转储文件。
  -XX:HeapDumpPath=/var/log/heapdump.hprof：指定堆转储文件的路径。
  -Xlog:gc*=info:file=portal_gc.log:utctime,level,tags:filecount=50,filesize=100M：指定GC日志的输出格式和位置，记录GC相关信息。
  -XX:+PrintCommandLineFlags：打印JVM启动时的命令行参数，可以去除
方便测试OOM，可以调整 -Xms524m -Xmx524m