1 通过JFR对某时段的cpu/耗时/内存分析
方法1: Async Profiler
下载地址: https://github.com/async-profiler/async-profiler/releases
- 优点:
- 轻量工具, 非侵入式修改字节码
- 完全避免安全点偏置问题
- 可直接监控native事件, 包括gc/jit编译调用链, malloc方法调用等
- linux环境可以直接使用perf_events, 监控cpu缓存命中率等jprofiler等工具无法采集的事件
- 支持指定方法(含native方法)的调用链追踪
- 缺点:
- 支持事件类型较少
JFR转html火焰图：
https://github.com/async-profiler/async-profiler/blob/master/docs/ConverterUsage.md
以wall火焰图为例
java -jar jfr-converter.jar --wall combined.jfr time.html
注：
-
html可能生成失败，jfr更可靠
-
idea自带的jfr分析只支持cpu和alloc功能。更多功能（如wall）建议使用Java Mission Control(JMC)/JProfiler(付费软件, 公司内提供)查看
-
不适用于死循环场景分析(代码行不够准确)，此时建议jstack观测线程栈信息
-
线程栈信息可能与jstack结果有偏差，此时以jstack结果为准
选项参考文档: https://github.com/async-profiler/async-profiler/blob/master/docs/ProfilerOptions.md
注: asprof位于解压文件的bin目录中
监控耗时 + 内存
# 计算密集型：
asprof -e cpu,alloc -d 60 -f combined.jfr <PID># IO密集型(墙钟耗时调用栈不清晰)：
asprof -e wall,alloc -d 60 -f combined.jfr <PID># 同时收集:
asprof -e wall,cpu,alloc -d 60 -f combined.jfr <PID># 全部收集(cpu, wall, alloc, live, nativemem, lock):
asprof --all -d 60 -f combined.jfr <PID>
-e cpu/wall,alloc: 同时监控 CPU/耗时 和内存分配
-d 60: 采样 60 秒
-f combined.jfr: 输出 JFR 格式文件
-e wall参数生成的jfr耗时部分无法通过idea查看，需要JMC打开，可以直接生成html火焰图，也可以jfr转换得到火焰图。
手动控制开始结束时间（推荐）
# 开始时：
asprof --all -f combined.jfr start <PID># 结束时(也可结束指定采样时长的任务)：
asprof -f combined.jfr stop <PID>
linux的perf事件类型(部分可能不支持)
https://github.com/async-profiler/async-profiler/blob/master/docs/ProfilingModes.md
| Usage | Description |
|---|---|
| Predefined: | |
-e cpu-clock |
High-resolution per-CPU timer. Similar to -e cpu but forces using perf_events. |
-e page-faults |
Software page faults |
-e context-switches |
Context switches |
-e cycles |
Total CPU cycles |
-e ref-cycles |
CPU reference cycles, not affected by CPU frequency scaling |
-e instructions |
Retired CPU instructions |
-e cache-references |
Cache accesses (usually Last Level Cache, but may depend on the architecture) |
-e cache-misses |
Cache accesses requiring fetching data from a higher-level cache or main memory |
-e branch-instructions |
Retired branch instructions |
-e branch-misses |
Mispredicted branch instructions |
-e bus-cycles |
Bus cycles |
-e L1-dcache-load-misses |
Cache misses on Level 1 Data Cache |
-e LLC-load-misses |
Cache misses on the Last Level Cache |
-e dTLB-load-misses |
Data load misses on the Translation Lookaside Buffer |
| Breakpoint: | |
-e mem:<addr> |
Breakpoint on a decimal or hex (0x) address |
-e mem:<func> |
Breakpoint on a public or a private symbol |
-e mem:<func>[+<offset>][/<len>][:rwx>] |
Breakpoint on a symbol or an address with offset, length and read/write/exec. Address, offset and length can be hex or dec. The format of mem event is the same as in perf-record. |
-e <symbol> |
Equivalent to an execution breakpoint on a symbol: mem:<symbol>:x. Example: -e strcmp will trace all calls of native strcmp function. |
| Tracepoint: | |
-e trace:<id> |
Kernel tracepoint with the given numeric id |
-e <tracepoint> |
Kernel tracepoint with the specified name. Example: -e syscalls:sys_enter_open will trace all open syscalls. |
| Probes: | |
-e kprobe:<func>[+<offset>] |
Kernel probe. Example: -e kprobe:do_sys_open. |
-e kretprobe:<func>[+<offset>] |
Kernel return probe. Example: -e kretprobe:do_sys_open. |
-e uprobe:<func>[+<offset>] |
Userspace probe. Example: -e uprobe:/usr/lib64/libc-2.17.so+0x114790. |
-e uretprobe:<func>[+<offset>] |
Userspace return probe |
| PMU: | |
-e r<NNN> |
Architecture-specific PMU event with the given number. Example: -e r4d2 selects MEM_LOAD_L3_HIT_RETIRED.XSNP_HITM event, which corresponds to event 0xd2, umask 0x4. |
-e <pmu descriptor> |
PMU event descriptor. Example: -e cpu/cache-misses/, -e cpu/event=0xd2,umask=4/. The same syntax can be used for uncore and vendor-specific events, e.g. amd_l3/event=0x01,umask=0x80/ |
# 可以结合--all, -e额外开启事件, 例如：
asprof --all -e page-faults,cycles,instructions,cache-misses -f combined.jfr start <PID>zhid
指定方法追踪调用链
https://github.com/async-profiler/async-profiler/discussions/1497
支持java方法/native方法追踪
###### java method ######
# example
java.util.SomeClass.someMethod# output of memory
java.lang.OutOfMemoryError.<init>###### native method ######
# trace humongous allocations of the G1 GC
G1CollectedHeap::humongous_obj_allocate# trace creation of new Java threads
JVM_StartThread# trace class loading
Java_java_lang_ClassLoader_defineClass1
无限制追踪(仅支持指定单个目标)
# 指定某个方法, 收集方法调用栈
asprof -e Demo.wasteTime -f latency.jfr <PID>
例如有以下代码:
import java.util.ArrayList;
import java.util.List;// 这里使用asprof -e JVM_GC 对native方法追踪,
public class Demo {private static void outofMemory(int round) {try {System.out.println("round: " + (round + 1));List<String> container = new ArrayList<>();String temp = "temp";for (int j = 0; j < 100; j++) {temp += temp;}String prefix = temp + temp + temp + temp + temp;for (int j = 0; j < 10000000; j++) {container.add(prefix + j + "suffix");}} catch (OutOfMemoryError e) {System.gc();System.out.println("invoke full gc");}}public static void main(String[] args) {for (int i = 0; i < 10; i++) {outofMemory(i);try {Thread.sleep(3000);} catch (InterruptedException e) {}}}
}
可以看到, 事件浏览器中, 能够正确采样到GC触发的调用链, 且不会收集到代码中其他部分
换用"java.lang.OutOfMemoryError.
根据真实耗时阈值过滤追踪(可指定多个目标)
# 指定某个方法耗时阈值, 收集超过阈值的方法调用栈
asprof --trace Demo.wasteTime:4s -f latency.jfr <PID> # 同时指定多个追踪目标
asprof --trace Demo.wasteTime:4s -f latency.jfr --trace Demo.outofMemory:300ms -f temp.jfr <PID>
例如有以下代码
import java.util.ArrayList;
import java.util.List;public class Demo {private static void wasteTime(int second) {try {System.out.println("should sleep " + second + " seconds");List<Integer> container = new ArrayList<>();for (int i = 0; i < 100000; i++) {container.add(i);}Thread.sleep(second * 1000L);} catch (InterruptedException e) {}}public static void someMethod(int depth, int second) {if (depth <= 0) {wasteTime(second);return;}someMethod(depth - 1, second);}public static void main(String[] args) {System.out.println("start");for (int i = 10; i >= 0; i--) {someMethod(i + 3, i);}}
}
可以从事件浏览器中看到, 能够正确过滤掉真实耗时不足4s的调用, 且调用链正确
方法2: 使用JDK自带的jcmd
- 优点:
- 事件类型丰富, 且支持自定义
- 非侵入式修改字节码
- cpu采样避免安全点偏置问题
- 缺点:
- JDK8或更早版本可能需要增加启动参数-XX:+UnlockCommercialFeatures -XX:+FlightRecorder
- 无法监控perf事件, 例如cpu缓存命中率
环境上可能只有jre, 需要自行上传jdk(JDK链接：https://jdk.java.net/archive/),,) 这里以jdk21为例
注: 虚拟线程栈经测试无问题
jcmd JFR.start参数
jcmd <PID> JFR.start \
name=MyRecording \ # 自定义任务名称
duration=60s \ # 记录时长（支持s/m/h/d）
filename=/path/output.jfr \ # 输出文件路径, 要求进程用户有该路径读写权限
settings=profile \ # 配置文件（profile记录更详细事件, 可自定义配置）
delay=5s \ # 延迟启动时间（避免启动瞬时干扰）
maxsize=1G \ # 文件最大大小（避免文件过大）
maxage=24h # 文件最大保留时间
使用jcmd记录jfr
- 启动记录(不写duration则保持记录, 直到手动JFR.stop)
jcmd <PID> JFR.start name=missionName settings=profile duration=10m filename=combined.jfr
例如:
监控10分钟
jcmd
不设置时限, 手动停止(调大jfr大小上限至500MB)
jcmd <PID> JFR.start name=missionName settings=profile maxsize=500MB filename=/tmp/combined.jfr
- 停止记录(可提前终止start的duration)
jcmd <PID> JFR.stop name=missionName
jfr配置进阶(IO为例)
修改jfr配置文件
profile.jfc的配置可能也不够详细, 可以手动修改配置文件传入, 如下就是根据profile.jfc, 增强io信息追踪的配置文件参考
配置中手动调整了io配置: threshold=0 ms表示记录所有文件读写操作, 无论耗时(默认 10 ms会过滤掉短时操作); period=everyChunk确保在数据块写入时持续记录，避免遗漏
此时如果io过多, 可能需要增加最大文件大小
jcmd <PID> JFR.start name=missionName settings=profile maxsize=800MB filename=/tmp/combined.jfr
此时, 我们可以关注FileWrite/SocketWrite等事件, 观察io情况
自定义jfr事件(需要同步修改java代码)(TODO)
https://yb.tencent.com/s/LEYucgLsqo6h
JMC火焰图手动开启
JMC地址: https://adoptium.net/zh-CN/jmc
建议使用idea查看cpu/内存火焰图(直接打开文件即可), 可以方便跳转函数
注: JMC火焰图手动开启
默认使用所有事件加权:
基于cpu采样权重:
可以多选择几种事件, 例如锁/io/cpu等, 更贴近真实耗时分布:
2 Arthas分析耗时, 内存, GC, 引用链等
下载地址: https://github.com/alibaba/arthas/releases
常用命令: https://arthas.aliyun.com/doc/commands.html
- 优点:
- 可以实时监控jvm, 功能齐全
- 内部集成async profiler, 具备全局分析能力
- 支持单点分析某次调用的具体情况(真实耗时分布, 入参等)
- 缺点:
- 侵入式修改字节码, 破坏JIT优化
- 热点函数修改导致的性能开销较大
- 需要监听端口
arthas使用java agent动态绑定到进程, 修改字节码进行操作
2.1 启动arthas, 选择进程
java -jar arthas-boot.jar
2.2 常用命令
注意: 修改类后, 建议及时reset, 避免持续产生影响
dashboard
作用：实时查看JVM整体状态（线程、内存、GC、运行环境等）
thread
作用：查看线程状态，排查CPU高占用、死锁等问题
thread # 查看所有线程
thread 10 # 查看线程ID=10的详细信息
thread -n 3 # 查看CPU占用前3的线程
thread -b # 查看死锁
stack
作用：查看方法被谁调用（定位调用链）
https://arthas.aliyun.com/doc/stack.html
# 查看getUser方法的调用栈
stack com.example.UserController getUser# 查询第一个参数大于100或第二个参数小于200, 且耗时超过50ms的调用栈. 最多查询2个
stack com.example.ServiceImpl myMethod '(params[0]>100 || params[1]<200) && #cost>50' -n 2
watch
作用：监控方法的参数、返回值、异常
https://arthas.aliyun.com/doc/watch.html
# 仅当第一个参数为'test'时观察
watch com.example.UserService getUser "{params[0], returnObj}" "params[0]=='test'"# 仅当执行时间大于100ms时观察
watch com.example.UserService getUser "{params, returnObj}" "#cost>100"# 监控类：com.example.UserService
# 监控方法：getUser（匹配所有以get开头的方法）
# 观察表达式：{params[0], returnObj, #cost} - 展示第一个参数、返回值和执行耗时
# 事件点：-b（调用前）和 -s（返回后） - 同时监控方法调用前和返回后
# 条件表达式：params[0] == 'admin' && #cost > 50 - 仅当第一个参数为'admin'且执行时间>50ms时触发
# 监控次数：-n 10 - 仅监控前10次匹配
# 输出深度：-x 3 - 展开嵌套对象的3层属性
# 正则匹配：-E - 使用正则表达式匹配类名和方法名
watch com.example.UserService -E 'get.*' "{params[0], returnObj, #cost}" -b -s "params[0]=='admin' && #cost>50" -n 10 -x 3
trace
作用：分析方法执行链路和耗时
https://arthas.aliyun.com/doc/trace.html
# 追踪UserService类中所有以get开头的方法
trace com.example.UserService get*# 仅追踪执行时间>100ms的调用
trace com.example.UserService getUser '#cost > 100'# 仅追踪执行时间超过50ms的getUser调用, 不跳过jdk方法
trace com.example.UserService getUser '#cost > 50' -n 10 --skipJDKMethod false
vmtool
作用: 深入到JVM内存层面, 触发GC, 中断线程, 直接查询, 操作内存中的对象实例等
功能较多, 这里举例说明
https://arthas.aliyun.com/doc/vmtool.html
- 获取实例(--action getInstances)
<font style="color:rgb(0, 0, 0);">vmtool --action getInstances --className 全路径类名 --limit 10</font>
- 分析堆内存占用(--action heapAnalyze)(4.1.5推出)
从 GC Root 可达对象出发, 统计各个类的实例数量与占用字节数, 输出占用最大的若干对象与类
# classNum: 指定展示的类数量; objectNum: 指定展示的对象数量
vmtool --action heapAnalyze --classNum 5 --objectNum 3
- 分析对象引用链(--action referenceAnalyze)(4.1.5推出)
分析某个类的实例对象，输出占用最大的若干对象及其引用回溯链
# className: 指定类名; objectNum: 前x大对象; backtraceNum: 回溯层级, -1直接回溯到root
vmtool --action referenceAnalyze --className java.lang.String --objectNum 5 --backtraceNum 3
3 JDK内存分析
MAT堆转储分析工具：https://eclipse.dev/mat/download/
JDK链接：https://jdk.java.net/archive/
3.1 某时刻堆内存统计
可以堆转储，将JVM中数据保存到hprof文件，然后使用MAT进一步分析，内存过高，内存泄漏时常用
# live会触发一次full gc
jmap -dump:live,format=b,file=dump.hprof <PID># 可使用jcmd, 也会触发full gc:
jcmd <PID> GC.heap_dump /path/to/dump.hprof# jstat统计堆内存占用分布情况, 更轻量
jstat -gc <PID> 1000 5 # 每秒采样1次，连续5次
堆转储导致的特殊full gc日志:
[2026-01-16T23:59:50.196+0800][237.011s][info][gc,start ] GC(10) Pause Full (Heap Dump Initiated GC)
[2026-01-16T23:59:50.196+0800][237.012s][info][gc,task ] GC(10) Using 4 workers of 15 for full compaction
[2026-01-16T23:59:50.196+0800][237.012s][info][gc,phases,start] GC(10) Phase 1: Mark live objects
[2026-01-16T23:59:50.209+0800][237.024s][info][gc,phases ] GC(10) Phase 1: Mark live objects 12.892ms
[2026-01-16T23:59:50.209+0800][237.025s][info][gc,phases,start] GC(10) Phase 2: Prepare compaction
[2026-01-16T23:59:50.212+0800][237.027s][info][gc,phases ] GC(10) Phase 2: Prepare compaction 2.743ms
[2026-01-16T23:59:50.212+0800][237.027s][info][gc,phases,start] GC(10) Phase 3: Adjust pointers
[2026-01-16T23:59:50.217+0800][237.032s][info][gc,phases ] GC(10) Phase 3: Adjust pointers 5.056ms
[2026-01-16T23:59:50.217+0800][237.032s][info][gc,phases,start] GC(10) Phase 4: Compact heap
[2026-01-16T23:59:50.221+0800][237.036s][info][gc,phases ] GC(10) Phase 4: Compact heap 4.014ms
[2026-01-16T23:59:50.221+0800][237.036s][info][gc,phases,start] GC(10) Phase 5: Reset Metadata
[2026-01-16T23:59:50.221+0800][237.037s][info][gc,phases ] GC(10) Phase 5: Reset Metadata 0.754ms
[2026-01-16T23:59:50.226+0800][237.041s][info][gc,heap ] GC(10) Eden regions: 17->0(30)
[2026-01-16T23:59:50.226+0800][237.041s][info][gc,heap ] GC(10) Survivor regions: 3->0(4)
[2026-01-16T23:59:50.226+0800][237.041s][info][gc,heap ] GC(10) Old regions: 5->9
[2026-01-16T23:59:50.226+0800][237.041s][info][gc,heap ] GC(10) Humongous regions: 0->0
[2026-01-16T23:59:50.226+0800][237.041s][info][gc,metaspace ] GC(10) Metaspace: 51935K(52800K)->51935K(52800K) NonClass: 44742K(45248K)->44742K(45248K) Class: 7192K(7552K)->7192K(7552K)
[2026-01-16T23:59:50.226+0800][237.041s][info][gc ] GC(10) Pause Full (Heap Dump Initiated GC) 97M->28M(200M) 29.742ms
[2026-01-16T23:59:50.226+0800][237.041s][info][gc,cpu ] GC(10) User=0.02s Sys=0.11s Real=0.03s
hprof文件可以用mat打开, 可以使用直方图等常用功能, 功能较多, 仅举例介绍.
查看支配树
使用OQL查找指定对象
根据线程找到对象的值
3.2 某时刻内存整体情况统计
观察瞬时概要
jcmd <PID> VM.native_memory summary
(base) gyt@XXSDDM:~$ jcmd 6892 VM.native_memory summary
6892: Native Memory Tracking: (Omitting categories weighting less than 1KB) Total: reserved=1548858KB, committed=386822KB malloc: 59442KB #237647 mmap: reserved=1489416KB, committed=327380KB - Java Heap (reserved=204800KB, committed=204800KB) (mmap: reserved=204800KB, committed=204800KB) - Class (reserved=1049804KB, committed=8780KB) (classes #13031) ( instance classes #12156, array classes #875) (malloc=1228KB #34814) (peak=1229KB #34817) (mmap: reserved=1048576KB, committed=7552KB) ( Metadata: ) ( reserved=65536KB, committed=45184KB) ( used=44775KB) ( waste=409KB =0.91%) ( Class space:) ( reserved=1048576KB, committed=7552KB) ( used=7184KB) ( waste=368KB =4.87%) - Thread (reserved=67767KB, committed=3679KB) (thread #67) (stack: reserved=67584KB, committed=3496KB) (malloc=107KB #407) (peak=131KB #461) (arena=75KB #130) (peak=498KB #92) - Code (reserved=50704KB, committed=17748KB) (malloc=1168KB #8037) (at peak) (mmap: reserved=49536KB, committed=16580KB) - GC (reserved=68511KB, committed=68415KB) (malloc=31583KB #5767) (peak=31583KB #5769) (mmap: reserved=36928KB, committed=36832KB) - GCCardSet (reserved=19KB, committed=19KB) (malloc=19KB #168) (peak=21KB #172) - Compiler (reserved=187KB, committed=187KB) (malloc=55KB #653) (peak=70KB #663) (arena=132KB #4) (peak=3944KB #13) - Internal (reserved=692KB, committed=692KB) (malloc=628KB #14122) (peak=638KB #14204) (mmap: reserved=64KB, committed=64KB) - Other (reserved=48KB, committed=48KB) (malloc=48KB #7) (peak=76KB #8) - Symbol (reserved=18963KB, committed=18963KB) (malloc=15982KB #155302) (at peak) (arena=2981KB #1) (at peak) - Native Memory Tracking (reserved=3779KB, committed=3779KB) (malloc=65KB #1149) (peak=66KB #1163) (tracking overhead=3713KB) - Shared class space (reserved=16384KB, committed=12864KB, readonly=0KB) (mmap: reserved=16384KB, committed=12864KB) - Arena Chunk (reserved=264KB, committed=264KB) (malloc=264KB #234) (peak=5936KB #292) - Module (reserved=271KB, committed=271KB) (malloc=271KB #3735) (at peak) - Safepoint (reserved=8KB, committed=8KB) (mmap: reserved=8KB, committed=8KB) - Synchronization (reserved=811KB, committed=811KB) (malloc=811KB #12933) (at peak) - Serviceability (reserved=17KB, committed=17KB) (malloc=17KB #16) (peak=17KB #18) - Metaspace (reserved=65810KB, committed=45458KB) (malloc=274KB #186) (at peak) (mmap: reserved=65536KB, committed=45184KB) - String Deduplication (reserved=1KB, committed=1KB) (malloc=1KB #8) (at peak) - Object Monitors (reserved=19KB, committed=19KB) (malloc=19KB #95) (at peak)
前后对比
# 确定参照基线作为对照
jcmd <PID> VM.native_memory baseline# 收集当前内存使用情况, 以baseline为基准对比
jcmd <PID> VM.native_memory summary.diff
(base) gyt@XXSDDM:~$ jcmd 6892 VM.native_memory baseline
6892:
Baseline taken (base) gyt@XXSDDM:~$ jcmd 6892 VM.native_memory summary.diff
6892: Native Memory Tracking: (Omitting categories weighting less than 1KB) Total: reserved=1561582KB +18105KB, committed=394690KB +8437KB - Java Heap (reserved=204800KB, committed=204800KB) (mmap: reserved=204800KB, committed=204800KB) - Class (reserved=1049941KB +128KB, committed=9365KB +576KB) (classes #13661 +618) ( instance classes #12739 +572, array classes #922 +46) (malloc=1365KB +128KB #37272 +2234) (mmap: reserved=1048576KB, committed=8000KB +448KB) : ( Metadata) ( reserved=65536KB, committed=47616KB +2368KB) ( used=47130KB +2335KB) ( waste=486KB =1.02% +33KB) : ( Class space) ( reserved=1048576KB, committed=8000KB +448KB) ( used=7570KB +379KB) ( waste=430KB =5.38% +69KB) - Thread (reserved=78034KB +15401KB, committed=4794KB +1501KB) (thread #77 +15) (stack: reserved=77824KB +15360KB, committed=4584KB +1460KB) (malloc=126KB +28KB #487 +110) (arena=84KB +13d #147 +25) - Code (reserved=50976KB +229KB, committed=19436KB +1645KB) (malloc=1440KB +229KB #9779 +1542) (mmap: reserved=49536KB, committed=17996KB +1416KB) - GC (reserved=68590KB +70KB, committed=68494KB +70KB) (malloc=31662KB +70KB #7559 +1666) (mmap: reserved=36928KB, committed=36832KB) - GCCardSet (reserved=19KB, committed=19KB) (malloc=19KB #167 -1) - Compiler (reserved=206KB +36KB, committed=206KB +36KB) (malloc=72KB +31KB #743 +95) (arena=135KB +5d #7 +5) - Internal (reserved=730KB +45KB, committed=730KB +45KB) (malloc=666KB +45KB #14868 +757) (mmap: reserved=64KB, committed=64KB) - Other (reserved=192KB +168KB, committed=192KB +168KB) (malloc=192KB +168KB #25 +21) - Symbol (reserved=19454KB +488KB, committed=19454KB +488KB) (malloc=16409KB +424KB #161163 +5804) (arena=3045KB +64d #1) - Native Memory Tracking (reserved=4002KB +213KB, committed=4002KB +213KB) (malloc=73KB +5KB #1284 +83) (tracking overhead=3929KB +208KB) - Shared class space (reserved=16384KB, committed=12864KB) (mmap: reserved=16384KB, committed=12864KB) - Arena Chunk (reserved=1225KB +1221KB, committed=1225KB +1221KB) (malloc=1225KB +1221KB) - Module (reserved=272KB +1KB, committed=272KB +1KB) (malloc=272KB +1KB #3753 +18) - Safepoint (reserved=8KB, committed=8KB) (mmap: reserved=8KB, committed=8KB) - Synchronization (reserved=854KB +43KB, committed=854KB +43KB) (malloc=854KB +43KB #13606 +654) - Serviceability (reserved=17KB, committed=17KB) (malloc=17KB #16) - Metaspace (reserved=65834KB +24KB, committed=47914KB +2392KB) (malloc=298KB +24KB #208 +22) (mmap: reserved=65536KB, committed=47616KB +2368KB) - String Deduplication (reserved=1KB, committed=1KB) (malloc=1KB #8) - Object Monitors (reserved=41KB +41KB, committed=41KB +41KB) (malloc=41KB +41KB #204 +201)
4 垃圾回收日志分析
任何gc在实际垃圾回收时，都会stop the world(STW)，过大的暂停耗时，可能会导致核心功能显著变慢，甚至丢失心跳导致重启。任何java服务的耗时分析，都不应该忽略gc过程产生的影响。
4.1 可视化分析gc日志
GCViewer
工具地址: https://github.com/chewiebug/GCViewer
需要启动gc日志, 根据-Xloggc地址查看gc日志, 例如
-Xlog:gc*:file=logs\gc.log:time,uptime,level,tags:filecount=10,filesize=100M
建议下载到windows本地后查看趋势图(趋势图不完全支持JDK21的gc日志格式)
java -jar gcviewer-1.36.jar gc.log
**注意留意gc吞吐量, gc吞吐量高不一定没有问题(例如读/写屏障并不暂停, 但实际上会降低程序效率), 但是低了一定有问题, **以及gc的STW耗时情况
GCeasy在线分析
工具地址: https://gceasy.io/
上传文件后直接分析即可
4.2 具体分析gc日志
4.2.1 JDK21 G1GC
young gc和根区域扫描冲突
例如下文, 可以看到GC(91)是一次young gc, 但是耗时过大, 接近1s, 可以看到中间发生了GC(90)的根扫描, 耗时953ms. 此时我们就可以认为, GC(91)的young gc暂停事件过大是因为中间夹带了一次并发标记阶段的根节点扫描
[2025-11-17T09:28:40.825+0800][1624.817s][info][gc ] GC(90) Concurrent Mark Cycle
[2025-11-17T09:28:40.825+0800][1624.817s][info][gc,cpu ] GC(89) User=4.53s Sys=0.00s Real=0.36s
[2025-11-17T09:28:40.825+0800][1624.817s][info][gc,marking ] GC(90) Concurrent Scan Root Regions
[2025-11-17T09:28:41.169+0800][1625.161s][info][gc,start ] GC(91) Pause Young (Normal) (G1 Evacuation Pause)
[2025-11-17T09:28:41.169+0800][1625.161s][info][gc,task ] GC(91) Using 13 workers of 13 for evacuation
[2025-11-17T09:28:41.778+0800][1625.770s][info][gc,marking ] GC(90) Concurrent Scan Root Regions 953.062ms
[2025-11-17T09:28:41.778+0800][1625.770s][info][gc,marking ] GC(90) Concurrent Mark
[2025-11-17T09:28:41.778+0800][1625.770s][info][gc,marking ] GC(90) Concurrent Mark From Roots
[2025-11-17T09:28:41.778+0800][1625.770s][info][gc,task ] GC(90) Using 3 workers of 3 for marking
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,phases ] GC(91) Pre Evacuate Collection Set: 1.0ms
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,phases ] GC(91) Merge Heap Roots: 0.7ms
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,phases ] GC(91) Evacuate Collection Set: 307.5ms
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,phases ] GC(91) Post Evacuate Collection Set: 3.7ms
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,phases ] GC(91) Other: 0.2ms
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,heap ] GC(91) Eden regions: 39->0(1209)
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,heap ] GC(91) Survivor regions: 100->7(18)
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,heap ] GC(91) Old regions: 901->1000
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,heap ] GC(91) Humongous regions: 51->51
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc,metaspace] GC(91) Metaspace: 175753K(177088K)->175753K(177088K) NonClass: 154148K(154816K)->154148K(154816K) Class: 21604K(22272K)->21604K(22272K)
[2025-11-17T09:28:42.091+0800][1626.083s][info][gc ] GC(91) Pause Young (Normal) (G1 Evacuation Pause) 17446M->16912M(40960M) 922.512ms
[2025-11-17T09:28:42.092+0800][1626.083s][info][gc,cpu ] GC(91) User=5.78s Sys=0.07s Real=0.92s
[2025-11-17T09:28:51.223+0800][1635.215s][info][gc,marking ] GC(90) Concurrent Mark From Roots 9444.744ms
[2025-11-17T09:28:51.223+0800][1635.215s][info][gc,marking ] GC(90) Concurrent Preclean
[2025-11-17T09:28:51.224+0800][1635.216s][info][gc,marking ] GC(90) Concurrent Preclean 1.253ms
[2025-11-17T09:28:51.251+0800][1635.243s][info][gc,start ] GC(90) Pause Remark
[2025-11-17T09:28:51.376+0800][1635.367s][info][gc ] GC(90) Pause Remark 27753M->24345M(40960M) 124.385ms
[2025-11-17T09:28:51.376+0800][1635.368s][info][gc,cpu ] GC(90) User=1.34s Sys=0.01s Real=0.13s
[2025-11-17T09:28:51.376+0800][1635.368s][info][gc,marking ] GC(90) Concurrent Mark 9597.759ms
[2025-11-17T09:28:51.376+0800][1635.368s][info][gc,marking ] GC(90) Concurrent Rebuild Remembered Sets and Scrub Regions
[2025-11-17T09:28:57.409+0800][1641.401s][info][gc,marking ] GC(90) Concurrent Rebuild Remembered Sets and Scrub Regions 6032.770ms
[2025-11-17T09:28:57.409+0800][1641.401s][info][gc,start ] GC(90) Pause Cleanup
[2025-11-17T09:28:57.411+0800][1641.403s][info][gc ] GC(90) Pause Cleanup 31648M->31648M(40960M) 1.958ms
[2025-11-17T09:28:57.411+0800][1641.403s][info][gc,cpu ] GC(90) User=0.01s Sys=0.00s Real=0.00s
[2025-11-17T09:28:57.411+0800][1641.403s][info][gc,marking ] GC(90) Concurrent Clear Claimed Marks
[2025-11-17T09:28:57.412+0800][1641.404s][info][gc,marking ] GC(90) Concurrent Clear Claimed Marks 0.359ms
[2025-11-17T09:28:57.412+0800][1641.404s][info][gc,marking ] GC(90) Concurrent Cleanup for Next Mark
[2025-11-17T09:28:57.433+0800][1641.424s][info][gc,marking ] GC(90) Concurrent Cleanup for Next Mark 20.891ms
[2025-11-17T09:28:57.433+0800][1641.425s][info][gc ] GC(90) Concurrent Mark Cycle 16607.868ms
young gc疏散失败
可以看到
[2026-01-14T09:25:14.486+0800][1464.752s][info][gc,start ] GC(76) Pause Young (Normal) (G1 Evacuation Pause)
[2026-01-14T09:25:14.487+0800][1464.752s][info][gc,task ] GC(76) Using 8 workers of 8 for evacuation
[2026-01-14T09:25:15.131+0800][1465.396s][info][gc,mmu ] GC(76) MMU target violated: 401.0ms (400.0ms/401.0ms)
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,phases ] GC(76) Pre Evacuate Collection Set: 0.52ms
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,phases ] GC(76) Merge Heap Roots: 1.69ms
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,phases ] GC(76) Evacuate Collection Set: 586.13ms
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,phases ] GC(76) Post Evacuate Collection Set: 56.27ms
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,phases ] GC(76) Other: 0.20ms
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,heap ] GC(76) Eden regions: 614->0(1)
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,heap ] GC(76) Survivor regions: 33->63(63)
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,heap ] GC(76) Old regions: 511->849
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,heap ] GC(76) Humongous regions: 59->59
[2026-01-14T09:25:15.131+0800][1465.397s][info][gc,metaspace] GC(76) Metaspace: 175354K(176768K)->175354K(176768K) NonClass: 153842K(154560K)->153842K(154560K) Class: 21512K(22208K)->21512K(22208K)
[2026-01-14T09:25:15.132+0800][1465.397s][info][gc ] GC(76) Pause Young (Normal) (G1 Evacuation Pause) (Evacuation Failure) 19464M->15536M(20480M) 645.022ms
[2026-01-14T09:25:15.132+0800][1465.397s][info][gc,cpu ] GC(76) User=4.84s Sys=0.00s Real=0.64s
可以看到关键词Pause Young (Normal) (G1 Evacuation Pause) (Evacuation Failure), 具体分析可以看到老年代和survivor的region增多. 当前现象是是survivor已经不足存放eden存活对象, 因此survivor需要增加区域, 且已达到上限区域数, ; 而多出来的存活对象直接晋升老年代, 因此, 老年代区域也发生增加
GC(76) Eden regions: 614->0(1)
GC(76) Survivor regions: 33->63(63) # survivor扩大, 最多63, 当前已使用63
GC(76) Old regions: 511->849 # 老年代扩大
类似的还有如下日志, 也是因为survivor分区数量不足, 晋升老年代, 疏散耗时过大
[2026-01-14T09:31:26.058+0800][1836.323s][info][gc,start ] GC(102) Pause Young (Concurrent Start) (G1 Humongous Allocation)
[2026-01-14T09:31:26.058+0800][1836.323s][info][gc,task ] GC(102) Using 8 workers of 8 for evacuation
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,mmu ] GC(102) MMU target violated: 401.0ms (400.0ms/401.0ms)
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,phases ] GC(102) Pre Evacuate Collection Set: 0.50ms
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,phases ] GC(102) Merge Heap Roots: 0.21ms
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,phases ] GC(102) Evacuate Collection Set: 511.73ms
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,phases ] GC(102) Post Evacuate Collection Set: 4.60ms
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,phases ] GC(102) Other: 0.16ms
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,heap ] GC(102) Eden regions: 74->0(764)
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,heap ] GC(102) Survivor regions: 76->4(29)
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,heap ] GC(102) Old regions: 288->362
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,heap ] GC(102) Humongous regions: 22->22
[2026-01-14T09:31:26.575+0800][1836.840s][info][gc,metaspace] GC(102) Metaspace: 175590K(177024K)->175590K(177024K) NonClass: 154070K(154816K)->154070K(154816K) Class: 21519K(22208K)->21519K(22208K)
[2026-01-14T09:31:26.575+0800][1836.841s][info][gc ] GC(102) Pause Young (Concurrent Start) (G1 Humongous Allocation) 7341M->6208M(20480M) 517.416ms
[2026-01-14T09:31:26.575+0800][1836.841s][info][gc ] GC(103) Concurrent Mark Cycle
[2026-01-14T09:31:26.575+0800][1836.841s][info][gc,cpu ] GC(102) User=3.79s Sys=0.03s Real=0.52s
Eden regions: 74->0(764)
GC(102) Survivor regions: 76->4(29) # 上轮GC分配的survivor区过少
GC(102) Old regions: 288->362 # 老年代扩大, eden/survivor->old
