本章主要讲解 JVM 的参数,重点讲解形如 -XX:[+,-]*
的非标准化参数。这些参数相对来说不稳定,随着 JVM 版本的变化可能会发生变化,主要用于 JVM 调优和 DEBUG。
GC 打印控制
按日志等级打印详情
Level: fine
-XX:+PrintGC
或
-XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=fine
输出内容如下:
0.149: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 102M->100M(256M), 0.0025488 secs]
0.152: [GC concurrent-root-region-scan-start]
0.152: [GC concurrent-root-region-scan-end, 0.0004812 secs]
0.152: [GC concurrent-mark-start]
0.152: [GC concurrent-mark-end, 0.0002496 secs]
0.156: [GC remark, 0.0016928 secs]
0.158: [GC cleanup 111M->111M(256M), 0.0005160 secs]
0.205: [Full GC (System.gc()) 211M->388K(8192K), 0.0207117 secs]
# JVM启动至今所经过的时间:GC类型 [回收前使用内存->回收后使用内存(总占用的内存)] [回收耗费的时间]
Level: finer
-XX:+PrintGCDetails
或
-XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=finer
输出内容如下:
0.141: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0017330 secs]
[Parallel Time: 1.3 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 140.9, Avg: 141.0, Max: 141.1, Diff: 0.1]
[Ext Root Scanning (ms): Min: 0.3, Avg: 0.3, Max: 0.5, Diff: 0.2, Sum: 2.6]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.2, Avg: 0.3, Max: 0.6, Diff: 0.4, Sum: 2.2]
[Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 3.7]
[Termination Attempts: Min: 1, Avg: 3.4, Max: 7, Diff: 6, Sum: 27]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 0.9, Avg: 1.1, Max: 1.2, Diff: 0.3, Sum: 8.6]
[GC Worker End (ms): Min: 141.9, Avg: 142.1, Max: 142.1, Diff: 0.2]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.1 ms]
[Other: 0.4 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.2 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 2048.0K(24.0M)->0.0B(24.0M) Survivors: 0.0B->1024.0K Heap: 102.0M(256.0M)->100.5M(256.0M)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
0.143: [GC concurrent-root-region-scan-start]
0.143: [GC concurrent-root-region-scan-end, 0.0003985 secs]
0.143: [GC concurrent-mark-start]
0.143: [GC concurrent-mark-end, 0.0002379 secs]
0.147: [GC remark 0.147: [Finalize Marking, 0.0002819 secs] 0.147: [GC ref-proc, 0.0000358 secs] 0.147: [Unloading, 0.0003903 secs], 0.0010815 secs]
[Times: user=0.01 sys=0.00, real=0.00 secs]
0.148: [GC cleanup 111M->111M(256M), 0.0003577 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
0.193: [Full GC (System.gc()) 211M->388K(8192K), 0.0145046 secs]
[Eden: 1024.0K(24.0M)->0.0B(3072.0K) Survivors: 1024.0K->0.0B Heap: 211.0M(256.0M)->388.9K(8192.0K)], [Metaspace: 3086K->3086K(1056768K)]
[Times: user=0.00 sys=0.01, real=0.01 secs]
Heap
garbage-first heap total 8192K, used 388K [0x00000006c0000000, 0x00000006c0100040, 0x00000007c0000000)
region size 1024K, 1 young (1024K), 0 survivors (0K)
Metaspace used 3093K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 339K, capacity 388K, committed 512K, reserved 1048576K
打印的 G1 的回收流程,以及各步骤回收的内存及执行的时间。
[Times: user=0.01 sys=0.00, real=0.01 secs]
# user CPU工作在用户态花费的时间(所有线程总和)
# sys CPU工作在内核态花费的时间(所有线程总和)
# real 此次GC事件花费的时间(真实时间)
Level: finest
-XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=finest
输出内容如下:
0.233: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0019984 secs]
[Parallel Time: 0.8 ms, GC Workers: 8]
[GC Worker Start (ms): 233.5 233.5 233.5 233.5 233.6 233.6 233.6 233.7
Min: 233.5, Avg: 233.6, Max: 233.7, Diff: 0.2]
[Ext Root Scanning (ms): 0.2 0.2 0.2 0.1 0.2 0.7 0.1 0.0
Min: 0.0, Avg: 0.2, Max: 0.7, Diff: 0.7, Sum: 1.6]
[Thread Roots (ms): 0.0 0.0 0.1 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[StringTable Roots (ms): 0.1 0.1 0.1 0.1 0.1 0.0 0.1 0.0
Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CLDG Roots (ms): 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.5 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.8]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Processed Buffers: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): 0.0 0.0 0.0 0.0 0.5 0.0 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.5]
[Termination (ms): 0.5 0.5 0.5 0.6 0.0 0.0 0.5 0.6
Min: 0.0, Avg: 0.4, Max: 0.6, Diff: 0.6, Sum: 3.2]
[Termination Attempts: 1 1 1 1 1 1 1 1
Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[GC Worker Total (ms): 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.6
Min: 0.6, Avg: 0.7, Max: 0.7, Diff: 0.1, Sum: 5.4]
[GC Worker End (ms): 234.2 234.2 234.2 234.2 234.2 234.2 234.2 234.2
Min: 234.2, Avg: 234.2, Max: 234.2, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 1.0 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.8 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Redirtied Cards: 0 0 0 0 0 0 0 0
Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
[Humongous Register: 0.0 ms]
[Humongous Total: 0]
[Humongous Candidate: 0]
[Humongous Reclaim: 0.0 ms]
[Humongous Reclaimed: 0]
[Free CSet: 0.0 ms]
[Young Free CSet: 0.0 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 1024.0K(3072.0K)->0.0B(3072.0K) Survivors: 0.0B->1024.0K Heap: 450.4K(8192.0K)->435.0K(8192.0K)]
[Times: user=0.01 sys=0.00, real=0.00 secs]
堆相关信息
堆使用信息
-XX:+UnlockDiagnosticVMOptions
-XX:+G1PrintRegionLivenessInfo
G1PrintRegionLivenessInfo 会输出大量日志,但限于并发标记周期的频率。如果你想分析你的旧区域在并发标记之后是什么样子的,以及在它们被 CSet 选择的效率是非常有用的。
输出内容如下:
### PHASE Post-Marking @ 0.215
# 并发标记后,所有分区的情况,包括Eden、Old、Survivor、Free、Humongous Start 和 Humongous Continues
### HEAP reserved: 0x00000006c0000000-0x00000007c0000000 region-size: 1048576
# -- 列表头介绍 --
# type 区域类型
# address-range 区域寻址范围
# used 区域已用空间
# prev-live 相对于之前标记周期的区域的活跃数据(用前一个TAMS和当前顶部之间的总和加上前一个标记# 周期中已知的活动对象(先前标记的)来衡量)
# next-live 标记后活跃数据空间(用下一个TAMS和当前顶部之间的总数加上当前标记周期中已知的活动对象(标记的)来衡量)
# gc-eff 区域GC效率(通过将可回收字节(已知活动字节减去总区域容量)除以收集区域的估计时间(RS扫描,对象复制和其他时间)来衡量的。效率越高,该地区就越适合作为候选地区)
# remset RSet大小(区域记忆集的大小,通过将区域表的大小与位图的大小乘以堆字大小来测量)
# code-roots CodeRoot大小(区域为强代码根所消耗的内存量,单位为字节)
### type address-range used prev-live next-live gc-eff remset code-roots
### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes)
### OLD 0x00000006c0000000-0x00000006c0100000 398256 398256 398256 0.0 3880 496
### FREE 0x00000006c0100000-0x00000006c0200000 0 0 0 0.0 3400 16
### FREE 0x00000006c0200000-0x00000006c0300000 0 0 0 0.0 3400 16
### FREE 0x00000006c0300000-0x00000006c0400000 0 0 0 0.0 3400 16
### FREE 0x00000006c0400000-0x00000006c0500000 0 0 0 0.0 3400 16
### FREE 0x00000006c0500000-0x00000006c0600000 0 0 0 0.0 3400 16
### SURV 0x00000006c0600000-0x00000006c0700000 47208 47208 47208 0.0 3400 16
### HUMS 0x00000006c0700000-0x00000006c0800000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0800000-0x00000006c0900000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0900000-0x00000006c0a00000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0a00000-0x00000006c0b00000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0b00000-0x00000006c0c00000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0c00000-0x00000006c0d00000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0d00000-0x00000006c0e00000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0e00000-0x00000006c0f00000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c0f00000-0x00000006c1000000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c1000000-0x00000006c1100000 1048576 1048576 1048576 0.0 3400 16
### HUMC 0x00000006c1100000-0x00000006c1200000 16 16 16 0.0 3400 16
### EDEN 0x00000006c1200000-0x00000006c1300000 125904 125904 125904 0.0 3400 16
###
### SUMMARY capacity: 19.00 MB used: 10.54 MB / 55.50 % prev-live: 10.54 MB / 55.50 % next-live: 10.54 MB / 55.50 % remset: 0.31 MB code-roots: 0.00 MB
### PHASE Post-Sorting @ 0.215
# CSet选择时需要对老生代分区进行排序,排序的依据是gc-eff,
# 这个值越大说明回收该分区的效率越高,所以会优先选择效率高的老生代分区
### HEAP reserved: 0x00000006c0000000-0x00000007c0000000 region-size: 1048576
###
### type address-range used prev-live next-live gc-eff remset code-roots
### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes)
### OLD 0x00000006c0000000-0x00000006c0100000 398256 398256 0 196560.1 3880 496
###
### SUMMARY capacity: 1.00 MB used: 0.38 MB / 37.98 % prev-live: 0.38 MB / 37.98 % next-live: 0.00 MB / 0.00 % remset: 0.25 MB code-roots: 0.00 MB
堆的分配和使用情况
-XX:+G1PrintHeapRegions
输出内容如下:
G1HR #StartFullGC 9
G1HR UNCOMMIT [0x00000006c0800000,0x00000006c0900000]
G1HR POST-COMPACTION(Old) 0x00000006c0000000 0x00000006c00612e0
G1HR #EndFullGC 9
210M->388K(8192K), 0.0204781 secs]
G1HR ALLOC(Eden) 0x00000006c0700000
G1HR #StartGC 10
G1HR CSET 0x00000006c0700000
G1HR ALLOC(Survivor) 0x00000006c0600000
G1HR RETIRE 0x00000006c0600000 0x00000006c0600b20
G1HR COMMIT [0x00000006c0800000,0x00000006c0900000]
G1HR #EndGC 10
470K->391K(16M), 0.0012499 secs]
FLAG | 解释 |
---|---|
COMMIT | 堆正在初始化或扩展,定义变更 Region 的 Top 和 Bottom 指针 |
ALLOC(Eden) | 由 Bottom 地址定义的区域被分配为 Eden 区域 |
CSET | CSET 选择的 Region,这些区域都会被回收 |
CLEANUP | 由 Bottom 地址定义的区域已经无可用对象,会在 concurrent marking 期间被清理 |
UNCOMMIT | 在 Full GC 后,如果堆缩小了,会有 UNCOMMIT 的 Region 集合 |
ALLOC(Old) | 由 Bottom 地址定义的区域被分配为 Old 区域 |
RETIRE | 在收集末期,最后分配的 Old Region 被标记为退休 |
REUSE | 在下一次收集开始,重用以前退休的 Region |
ALLOC(Survivor) | 由 Bottom 地址定义的区域被分配为 Survivor 区域 |
EVAC-FAILURE | 标记收集期间发生的 evacuation failure 事件对应的 Region |
POST-COMPACTION(Old) | Full GC 后,包含 live data 的 Humongous regions 会被标记为 post-compaction |
ALLOC(SingleH) | 由底部和顶部地址定义的区域被分配为一个单一的Humongous区域,当对象适合分配一个单一的区域 |
ALLOC(StartsH) | 由顶部地址定义的区域被分配为一个 Starts Humongous region,当对象跨度超过单个 Region 空间 |
打印堆 Region 事件只有在调试特定问题时才有必要,例如:
- 调试 Evacuation Failure 和失败的区域数量
- 确定 Humongous objects 的大小和频率
- 跟踪和评估 Eden、Survivor 和 Old Region的数量,作为 CSet 的一部分被分配和收集
当没有更多的空闲 Region 被提升到老一代或者复制到幸存空间时,并且由于堆已经达到最大值,堆不能扩展,从而发生 Evacuation Failure
输出 GC 前后的堆概要信息
-XX:+PrintHeapAtGC
输出内容如下:
{Heap before GC invocations=12 (full 4):
garbage-first heap total 8192K, used 388K [0x00000006c0000000, 0x00000006c0100040, 0x00000007c0000000)
region size 1024K, 1 young (1024K), 0 survivors (0K)
Metaspace used 3086K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 338K, capacity 388K, committed 512K, reserved 1048576K
0.557: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 470K->390K(16M), 0.0006541 secs]
Heap after GC invocations=13 (full 4):
garbage-first heap total 16384K, used 390K [0x00000006c0000000, 0x00000006c0100080, 0x00000007c0000000)
region size 1024K, 1 young (1024K), 1 survivors (1024K)
Metaspace used 3086K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 338K, capacity 388K, committed 512K, reserved 1048576K
}
0.558: [GC concurrent-root-region-scan-start]
0.558: [GC concurrent-root-region-scan-end, 0.0000694 secs]
0.558: [GC concurrent-mark-start]
0.558: [GC concurrent-mark-end, 0.0004754 secs]
0.562: [GC remark, 0.0008506 secs]
0.567: [GC cleanup 20M->20M(38M), 0.0003862 secs]
{Heap before GC invocations=14 (full 4):
garbage-first heap total 252928K, used 215431K [0x00000006c0000000, 0x00000006c01007b8, 0x00000007c0000000)
region size 1024K, 2 young (2048K), 1 survivors (1024K)
Metaspace used 3086K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 338K, capacity 388K, committed 512K, reserved 1048576K
0.651: [Full GC (System.gc()) 210M->388K(8192K), 0.0195430 secs]
Heap after GC invocations=15 (full 5):
garbage-first heap total 8192K, used 388K [0x00000006c0000000, 0x00000006c0100040, 0x00000007c0000000)
region size 1024K, 0 young (0K), 0 survivors (0K)
Metaspace used 3086K, capacity 4496K, committed 4864K, reserved 1056768K
class space used 338K, capacity 388K, committed 512K, reserved 1048576K
}
Heap before GC
和 Heap after GC
分别表示 GC 前后堆的信息的开始,invocations 表示调用堆信息输出的次数(Heap after GC
对应的 invocations 除 2,即为 GC 的次数),而 full 表示第几次 Full GC。
GC 通用过程信息
输出日志打印日期
-XX:+PrintGCTimeStamps # 将时间加到GC日志(G1默认开启)
-XX:+PrintGCDateStamps # 将日期加到GC日志
输出内容如下:
2022-07-21T15:50:40.086-0800: 0.555: [GC concurrent-root-region-scan-start]
输出GC过程中关于SafePoint的应用时间
-XX:+PrintGCApplicationConcurrentTime # GC时打印安全点间应用线程执行时间
-XX:+PrintGCApplicationStoppedTime # GC时打印安全点间应用线程停顿时间
输出内容如下:
# -XX:+PrintGCApplicationConcurrentTime 安全点间应用线程执行时间
Application time: 0.2222222 seconds
# -XX:+PrintGCApplicationStoppedTime 安全点间应用线程停顿时间
Total time for which application thread were stopped: 0.222222 seconds
# -XX:+PrintGCApplicationStoppedTime 暂停全部应用线程进入安全点的时间
Stopping threads took: 0.0005178 seconds
GC 功能性信息
输出新生代到老年代晋升的情况
# 适用于YGC
-XX:+PrintTenuringDistribution
输出内容如下:
332.036: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
Desired survivor size 223674368 bytes, new threshold 15 (max 15)
- age 1: 63634632 bytes, 63634632 total
- age 2: 1064928 bytes, 64699560 total
- age 3: 24489776 bytes, 89189336 total
: 1795001K->92332K(2184576K), 0.1389036 secs] 1960821K->258153K(4806016K), 0.1390975 secs] [Times: user=0.37 sys=0.16, real=0.14 secs]
我们需要知道,我们是可以通过 MaxTenuringThreshold 参数控制对象从新生代晋升到老年代经过 GC 次数的最大值,这个默认值是 15,而最大值也是 15,因为对象头里给了 4个 bit 存放,只能表示 15 以内的整数。这个参数并非能达到绝对控制,比如晋升失败会导致对象原地不动,如果 survival 区不够大,可能直接放到老年代。
这时候 Survivor 的大小是 223674368 字节,new threshold 15
表示 age 为 15 的对象都将送入到老生代分区,最大的年代数是 15。当前 age1 有 63634632 字节,age2 有 1064928 字节,age3 有 24489776 字节,total 是当前加起来的总和。
输出并发标记概要信息
-XX:+UnlockDiagnosticVMOptions
-XX:+G1SummarizeConcMark
输出内容如下:
Concurrent marking:
0 init marks: total time = 0.00 s (avg = 0.00 ms).
5 remarks: total time = 0.01 s (avg = 1.45 ms).
[std. dev = 0.49 ms, max = 1.81 ms]
# remark有5个历史数据,给出了均值、最大值
5 final marks: total time = 0.00 s (avg = 0.79 ms).
[std. dev = 0.43 ms, max = 1.18 ms]
5 weak refs: total time = 0.00 s (avg = 0.66 ms).
[std. dev = 0.13 ms, max = 0.86 ms]
5 cleanups: total time = 0.00 s (avg = 0.40 ms).
[std. dev = 0.06 ms, max = 0.48 ms]
Final counting total time = 0.00 s (avg = 0.10 ms).
# 并发标记的最后,对分区对象进行计数的时间花费
RS scrub total time = 0.00 s (avg = 0.10 ms).
# 处理RSet的花费
Total stop_world time = 0.01 s.
# 初始化、再标记、清理的时间
Total concurrent time = 0.76 s ( 0.01 s marking).
# 并发线程总花费和标记时间花费
输出安全点相关信息
-XX:+PrintSafepointStatistics # 输出安全点信息
-XX:PrintSafepointStatisticsCount=n # 每n次进入安全点输出1次信息
输出大对象日志分析
# 适用于YGC
-XX:+UnlockExperimentalVMOptions
-XX:+G1TraceEagerReclaimHumongousObjects
输出日志如下:
Live humongous region 0 size 4194320 start 0x00000000f0000000 length 5 with remset 8194 code roots 0 is marked 0 reclaim candidate 0 type array 0
以上日志表示 0 号分区活跃大对象分区为 4M;起始地址为 0x00000000f0000000,占用 5 个分区;RSet 更新过 8194 次,代码块长度为 0,并有被标记;reclaim candidate 0
表示不能被回收;type array 0
表示不是数组类型。
输出G1自适应详细信息
-XX:+PrintAdaptiveSizePolicy
输出 G1 的自适应策略相关的 GC 日志,其中包括发生相关事件的原因及部分事件的时间预测等。
输出内容如下:
0.187: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 0.187: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 10.00 ms, remaining time: 190.00 ms, target pause time: 200.00 ms]
# 预测了处理 DirtyCard 的时间, 包含 Update RS 和 Scan RS
0.187: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 2 regions, survivors: 0 regions, predicted young region time: 30.60 ms]
# 预测了将 Region 加入到 CSet 的时间,包含对象的拷贝时间
0.187: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 2 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 40.60 ms, target pause time: 200.00 ms]
# 预测了基本时间和年轻代Region的CSet处理时间
102M->100M(256M), 0.0057796 secs]
0.218: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 149946368 bytes, allocation request: 10485776 bytes, threshold: 120795930 bytes (45.00 %), source: concurrent humongous allocation]
0.262: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 230686720 bytes, allocation request: 10485776 bytes, threshold: 120795930 bytes (45.00 %), source: concurrent humongous allocation]
输出 Ref 处理信息
-XX:+PrintReferenceGC
打印处理引用的时间消耗
2021-02-19T12:41:30.462+0800: 5072726.605: [SoftReference, 0 refs, 0.0000521 secs] 2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs] 2021-02-19T12:41:30.462+0800: 5072726.605: [FinalReference, 0 refs, 0.0000056 secs] 2021-02-19T12:41:30.462+0800: 5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs] 2021-02-19T12:41:30.462+0800: 5072726.605: [JNI Weak Reference, 0.0000131 secs], 0.4635293 secs]
GC 文件输出
Log文件输出
# 根据时间戳生成日志名
-Xloggc:gc-%t.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation
# 最多分割几个文件,超过之后从头开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小,超过就触发分割
-XX:GCLogFileSize=100M
Dump文件输出
-XX:+HeapDumpOnOutOfMemoryError
GC 功能性参数
分配物理内存
-XX:+AlwaysPreTouch
服务启动的时候真实的分配物理内存给 JVM。如果没有此参数,则 JVM 启动的时候,分配的只是虚拟内存,当真正使用的时候才会分配物理内存,导致代码运行速度变慢;如果有此参数,则 JVM 启动的时候速度会下降很多。
GC 引用调优相关参数
引用相关日志输出:
-XX:+PrintReferenceGC
-XX:+TraceReferenceGC
ParallelRefProcBalancingEnabled
参数 ParallelRefProcBalancingEnabled,默认值为 true,在处理引用的时候,引用(软/弱/虚/final/cleaner)对象在同一类型的队列中可能是不均衡的,如果打开该参数则表示可以把链表均衡一下。注意这里的均衡不是指不同引用类型之间的均衡,而是同一引用类型里面有多个队列,同一引用类型多个队列之间的均衡。
ParallelRefProcEnabled
参数ParallelRefProcEnabled,默认值为 false,打开之后表示在处理一个引用的时候可以使用多线程的处理方式。这个参数主要是控制引用列表的并发处理。另外引用的处理在 GC 回收和并发标记中都会执行,在 GC 中执行的引用处理使用的线程数目和 GC 线程数目一致,在并发标记中处理引用使用的线程数目和并发标记线程数一致。实际中通常打开该值,减少引用处理的时间。
RegisterReferences
参数 RegisterReferences,默认值 true,表示可以在遍历对象的时候发现引用对象类型中的对象是否可以回收,false 表示在遍历对象的时候不处理引用对象。目前的设计中在 GC 发生时不会去遍历引用对象是否可以回收。需要注意的是该参数如果设置为 false,则在 GC 时会执行软引用对象是否可以回收,这将会增加 GC 的时间,所以通常不要修改这个值。
G1UseConcMarkReferenceProcessing
参数 G1UseConcMarkReferenceProcessing,默认值 true,表示在并发标记的时候发现对象。
RefDiscoveryPolicy
参数 RefDiscoveryPolicy,默认值为 0,0 表示 ReferenceBasedDiscovery,指如果引用对象在我们的处理范围内,则对这个引用对象进行处理。1 表示 ReferentBasedDiscovery,指如果引用对象在我们的处理范围内或者引用对象里面的对象在处理范围内,则对引用对象处理。1 会导致处理的对象更多。
SoftRefLRUPolicyMSPerMB
参数 SoftRefLRUPolicyMSPerMB,默认值为 1000,即对软引用的清除参数为每 MB 的内存将会存活 1s,如最大内存为 1GB,则软引用的存活时间为 1024s,大约为 17 分钟,但是如果内存为 100GB,这个参数不调整,软引用对象将存活 102 400s,大约为 28.5小时。所以需要根据总内存大小以及预期软引用的存活时间来调整这个参数。
GC 字符串去重调优相关参数
字符串去重相关日志输出:
-XX:+PrintStringDeduplicationStatistics
0.317: [GC pause (G1 Evacuation Pause) (young) 33M->36M(512M), 0.1230416 secs]
0.440: [GC concurrent-string-deduplication, 62.7K->37.3K(25.3K), avg 40.1%, 0.0002402 secs]
[Last Exec: 0.0002402 secs, Idle: 0.1289596 secs, Blocked: 0/0.0000000 secs]
[Inspected: 1368]
[Skipped: 0( 0.0%)]
字符串为null则跳过
[Hashed: 255( 18.6%)]
字符串哈希值不为0
[Known: 887( 64.8%)]
字符串共享的次数
[New: 481( 35.2%) 62.7K]
字符串新加入HashTable的次数
[Deduplicated: 201( 41.8%) 25.3K( 40.4%)]
[Young: 0( 0.0%) 0.0B( 0.0%)]
字符串在新生代的个数
[Old: 201(100.0%) 25.3K(100.0%)]
字符串在老生代的个数
[Total Exec: 2/0.0002457 secs, Idle: 2/0.2149240 secs, Blocked: 0/0.0000000 secs]
# 发生GC或并发标记时进行去重总的统计时间,已经发生了2次
[Inspected: 1371]
[Skipped: 0( 0.0%)]
[Hashed: 258( 18.8%)]
[Known: 887( 64.7%)]
[New: 484( 35.3%) 63.1K]
[Deduplicated: 201( 41.5%) 25.3K( 40.1%)]
[Young: 0( 0.0%) 0.0B( 0.0%)]
[Old: 201(100.0%) 25.3K(100.0%)]
[Table]
[Memory Usage: 35.4K]
[Size: 1024, Min: 1024, Max: 16777216]
[Entries: 1170, Load: 114.3%, Cached: 0, Added: 1170, Removed: 0]
[Resize Count: 0, Shrink Threshold: 682(66.7%), Grow Threshold: 2048(200.0%)]
[Rehash Count: 0, Rehash Threshold: 120, Hash Seed: 0x0]
[Age Threshold: 3]
[Queue]
[Dropped: 0]
# 字符串超过队列长度丢弃次数
[GC concurrent-string-deduplication, deleted 0 entries, 0.0000006 secs]
UseStringDeduplication
参数 UseStringDeduplication,默认值为 false,打开参数表示允许字符串去重。
StringDeduplicationAgeThreshold
参数 StringDeduplicationAgeThreshold,默认值为 3,控制字符串是否参与去重的阈值。虽然字符串去重能明显减少内存的使用,但是这会增加 GC 处理的时间。
GC 安全点调优相关参数
安全点输出相关日志输出:
-XX:+PrintSafepointStatistics # 输出安全点信息
-XX:PrintSafepointStatisticsCount=1 # 每一次进入安全点都输出信息额外增加的输出参数:
-XX:+PrintGCApplicationConcurrentTime
-XX:+PrintGCApplicationStoppedTime
Application time: 0.0441187 seconds
vmop
# vmop:指从执行VM操作开始到结束所花费的时间。
[threads: total initially_running wait_to_block]
[time: spin block sync cleanup vmop]
# 时间信息含义如下:
# spin:指的是如果在进入安全点时,有正在运行的线程,那么VMThread需要等待其他线程
# 让出CPU,为了避免上下文的切换,VMThread优先选择自旋。这个时间指的是从进
# 入安全点到所有线程都不再运行的时间。
# block:指的是如果有线程需要阻塞所花费的时间。注意阻塞和上面提到的运行是不同的状态,
# 当线程不处于运行状态时,也并不一定是阻塞状态。
# sync:指的是spin和block的总和。
# cleanup: 包括几个任务花费的时间。任务主要有:
# 1.对Monitor降级。
# 2.对inlinecache(JVM为了优化而提供)缓存处理。
# 3.对JIT编译策略调整。
# 4.如果符号表的个数超过负载均衡因子(60%)可以进行rehash,创建新的符号表。
# 5.如果字符串表(用于intern)的个数超过负载均衡因子(60%)可以进行rehash,
# 创建新的字符串表。
# 6.JIT编译代码回收。
page_trap_count 0.132:
# page_trap_count:指的是编译线程通过设置轮询页面不可读进入到安全点的次数。
G1IncCollectionPause
# G1IncCollectionPause 表示在增量GC,对G1来说可能是YGC或是MGC
[ 11 0 0 ]
# 1. 有11个线程
# 2. 0 表示在打印这个信息的时候没有正在运行的线程
# 3. 0 表示在进入安全点的过程中有0个线程正待被阻塞。
[ 0 0 0 0 1 ] 0
Total time for which application threads were stopped: 0.0018904 seconds, Stopping threads took: 0.0000319 seconds
Polling page always armed
CGC_Operation 2
G1IncCollectionPause 1
0 VM operations coalesced during safepoint
Maximum sync time 4 ms
Maximum vm operation time (except for Exit VM operation) 1 ms
不同的线程进入安全点的时间可能各不相同,特别在编译线程中,如果有一个超级大的循环,假设在 JIT 编译中没有在循环中插入安全点,那么循环可能一直执行,导致有编译的线程一直不能进入到安全点。JDK 9 中引入新的参数 UseCountedLoopSafepoints,可打开该参数,允许在循环中插入安全点。
在进入真正的 VM 操作之前,还需要做一些任务清理工作,这个工作当然也有可能导致进入安全点时间过长。这些工作主要有:Monitor 降级处理、JIT编译代码回收、符号表和字符串表回收。
Monitor降级
Java 提供了 Synchronized 的关键字,其锁主要存在4种状态,依次是:无锁状态、偏向锁状态、轻量级锁状态、重量级锁状态,他们会随着竞争的激烈而逐渐升级。
在安全点的时候如果发现锁是空闲的就可以对锁进行降级。有一个参数 MonitorInUseLists(默认值为false),打开该参数表示只对正在使用的 Monitor 进行降级(正在使用的意思指的是只关注在线程栈里面使用的 Monitor),该参数关闭的话则对所有的 Monitor 进行降级。如果你使用的是JDK8或者之前的版本,当发现安全点上有大量的Monitor,可以尝试做两件事:
- 打开 MonitorInUseLists,减少 Monitor 降级处理。
- 使用 JUC 里面的 lock 来代替 Synchronized。
JIT编译代码回收
有一个参数 MethodFlushing(默认值为true),该参数表示回收已经不再使用的编译代码。如果发现有大量的编译代码回收导致进入安全点时间过长,可以考虑关闭该参数,但是带来的问题很有可能是填满了 JIT 编译代码缓存,从而导致编译停止,引起性能问题。
符号表和字符串表回收字符串表回收是指 String 的 intern 处理,如果使用大量的 String 的 intern 方法也有可能导致进入安全点时间过长,如果发生这种情况,可以考虑:
- 设置 StringTable 的长度 StringTableSize(这个长度就是intern使用hashTable的长度),在64位机器默认值为60013,32位机器为1009。可以增大该值。
- 也可以考虑不再使用 intern,而使用 G1 的字符串去重功能。符号表 SymbolTable 的调整和 StringTable 类似,也可以设置参数 SymbolTableSize(默认值为20011)来减少 rehash 操作。
TODO 参数
-XX:+DisableExplicitGC
-XX:+DebugNonSafepoints
-XX:+FlightRecorder
-XX:FlightRecorderOptions=stackdepth=500
-XX:-OmitStackTraceInFastThrow
-XX:+TrustFinalNonStaticFields
-XX:+UnlockCommercialFeatures
-XX:+UseCompressedClassPointers
-XX:+UseCompressedOops
-XX:+G1ConcRegionFreeingVerbose
-XX:+G1SummarizeRSetStats
-XX:G1SummarizeRSetStatsPeriod=1