老司机 Kyle 又一次问我有没有兴趣查一个问题, 直接扔过来一个app的监控 dashboard, 又是 GC overhead 100%. 不过这次有点曲折.
监控数据如下:
解读:
- GC overhead 100%, 也就是Java 进程占用的CPU 全部用来做GC 了;
- JVM CPU usage 从20% 升到了35%, 也就是Java 进程使用的CPU 量增加了很多;
- OOM 的数量从0变成了每秒几个;
- 有意思的是 Java 的可用heap 从2G 突然变成了5.1G.
背景相关:
这个app 设置的Java heap 是5.5G.
从上面信息大致可以猜测, 可能遇到如下问题:
- 大量调用 System.gc() 或 Runtime.gc();
- Metaspace (或Java8之前永久代) 用尽;
- 或者 Native 内存被用尽;
于是使用 jstat 命令查看 gccause:
$ jdk/bin/jstat -gccause 1075 2000 5
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT LGCC GCC
0.00 100.00 0.00 4.14 69.08 32.72 48945 2441.067 1848 806.736 3247.803 Metadata GC Threshold Metadata GC Threshold
0.00 0.00 0.00 4.55 69.08 32.72 48947 2441.076 1853 808.914 3249.990 Metadata GC Threshold Last ditch collection
0.00 100.00 0.00 5.07 69.08 32.72 48950 2441.092 1858 811.101 3252.193 Metadata GC Threshold Metadata GC Threshold
0.00 100.00 0.00 4.82 69.08 32.72 48952 2441.102 1862 812.887 3253.989 Metadata GC Threshold Metadata GC Threshold
0.00 0.00 0.00 3.93 69.08 32.72 48954 2441.111 1867 815.072 3256.183 Metadata GC Threshold Last ditch collection
上面各列名的解释:
S0: Survive 0; S1: Survive 1; E: Eden; O: Old; M: Metaspace; CCS: Compressed class; YGC: Young GC Count; YGCT: Young GC Time; FGC: Full GC Count; FGCT: Full GC Time; GCT: GC Time; LGCC: Last GC Cause; GCC: GC Cause this time.
从上面统计数据可以看到: Full GC(FGC) 的数量在持续的10s 内持续增加, 造成的原因就是: Metadata GC Threshold 和 Last ditch collection.
在解释上面2个原因之前, 我们可以看看 Metaspace 的使用策略. Metaspace 是用来替换之前的永久代的, 并且从Native 内存申请, 用来存放类的元数据. 从操作系统申请的native 内存被分成 chunks, 每个chunk 被分配给每个 ClassLoader, 这个chunk里面的class 如果全部被回收的时候, 这个 chunk 也会被回收. 另外这些Native 内存使用mmap分配, 不是使用malloc.
从网上找来一张好图:
上面图上有几个概念:
- reserved: Java 应用虚拟内存里面保留的大小, 这个这是虚拟内存申请量, 和实际使用量没关系;
- committed: 从操作系统(OS)里面申请的 native 内存的大小, 被分为若干个不同大小的 chunks;
- capacity: 被分配给 ClassLoader 的所有 chunk 内存之和, 不包含没被分配的 free chunk;
- chunk: 分成2种: 被分配给classLoader的和未被分配的;
- used: 所有被分配的 chunk 里面的使用量之和. 一个被分配的chunk 也是慢慢被使用完的.
上面图里面没有涉及到的概念: - Metaspace occupied threshold(high watermark), 它一般是committed 的一个百分比, 由 -XX:MaxMetaspaceFreeRatio 和 -XX:MinMetaspaceFreeRatio 这个2个参数决定.
当 ClassLoader 要分配一个新的class空间的时候, 它检查自己拥有的chunk, 如果当前拥有的chunk内部空间不足的时候, 就会去free chunk 里申请一个新的chunk. JVM 内部维护一个metaspace 已经被占用的 threshold (high watermark), 当已经占用的量(capacity) 触及这个 threshold 的时候, 就会触发一个 Full GC (Metadata GC Threshold) GC. 当这个Full GC 还不能回收到足够的空间时, 就会看到 Full GC (Last ditch collection).
verbose GC log 里面的日志:
2022-10-01T18:11:27.974-0700: 407174.877: [Full GC (Metadata GC Threshold) 2022-10-01T18:11:27.974-0700: 407174.877: [GC concurrent-root-region-scan-end, 0.0001638 secs]
2022-10-01T18:11:27.974-0700: 407174.877: [GC concurrent-mark-start]
189M->189M(5120M), 0.4585377 secs]
[Eden: 0.0B(390.0M)->0.0B(390.0M) Survivors: 2048.0K->0.0B Heap: 189.4M(5120.0M)->189.4M(5120.0M)], [Metaspace: 362167K->362167K(1525760K)]
Heap after GC invocations=50066 (full 1356):
garbage-first heap total 5242880K, used 193982K [0x00000006a0800000, 0x00000006a0a05000, 0x00000007e0800000)
region size 2048K, 0 young (0K), 0 survivors (0K)
Metaspace used 362167K, capacity 367544K, committed 524288K, reserved 1525760K
class space used 15775K, capacity 16721K, committed 48228K, reserved 1048576K
}
[Times: user=0.65 sys=0.01, real=0.46 secs]
{Heap before GC invocations=50066 (full 1356):
garbage-first heap total 5242880K, used 193982K [0x00000006a0800000, 0x00000006a0a05000, 0x00000007e0800000)
region size 2048K, 0 young (0K), 0 survivors (0K)
Metaspace used 362167K, capacity 367544K, committed 524288K, reserved 1525760K
class space used 15775K, capacity 16721K, committed 48228K, reserved 1048576K
2022-10-01T18:11:28.433-0700: 407175.336: [Full GC (Last ditch collection) 189M->189M(5120M), 0.4538734 secs]
-- 未完待续
