巨大的 CopyOnWriteArrayList 导致的频繁 full GC 的症状
前2天看到有台机器的 Java 应用突然 CPU 高企, 再看其它metrics, 发现是由 GC 导致的, 但是看到 JVM available 内存, 却有很多, 再去观察 verboseGC log, 形状也很奇怪. 它到底是什么原因导致的呢?
分类 Troubleshooting 相关 下的文章
诊断docker container 里面的 Java 进程内存泄漏
在公司有台台式机, 平时办公不用它, CPU 性能还可以, 有16G 内存, 为了充分利用它, 在它上面装了docker, 然后通过container的方式安装了不少工具, 比如: MySQL+phpmyadmin, ElasticSearch+kibana, MongoDB+mongoUI, Splunk, Clickhouse, Prometheus, Jupter Notebook, Neo4J, Janusgraph, Nginx 等应用, 平时做个测试或者小工具, 直接连这些应用, 非常方便. 直到有一天, 给它接了一个外接显示器, 第二天早上看到下面这个系统日志, 发现这个上面有个应用一直OOM.
诊断 ThreadLocal 引起的内存泄漏
今天遇到一起由于 ThreadLocal 没有正确使用引起的内存泄漏, 诊断过程中有些推断步骤还是有值得借鉴的意义的. 1: 如何快速找到当前线程中占用最大内存的对象; 2: 如何找到 ThreadLocal 变量的代码点.
为啥 java.lang.ThreadGroup 把内存干爆了
最近分析了一个 Java 内存泄漏的例子, 干爆内存的不是业务对象, 竟然是 1162 万个 java.lang.ThreadGroup 对象. 到底是谁这么丧心病狂的创建这么多 ThreadGroup 又不释放呢? 为啥干爆 heap 的不是 ThreadGroup 里面的 Thread 呢?
Java Metaspace 造成的full GC
老司机 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]-- 未完待续