1、问题
最近有个sso 服务频繁的oom,而且并不是达到JVM上限导致的OOM,而是达到了K8S设置的上限,被K8S Kill掉的,所以没有dump日志。回去看了下日志,一共有两个实例,原先内存分配应该是3G 的时候,平均一个节点一天要被Kill掉十几次。。后来增大到6G 内存,也只是让他能多跑一会,有时候两三天才OOM 一次。
2、DUMP 日志排查
让运维协助加上了-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath= 和-Xmx 限制后重新启动了服务,希望让JVM 自己OOM退出并dump下来日志,观察了几天后都没有出现OOM,于是在后几天内存占用量高的时候dump出了日志并没有发现任何异常。
编辑
编辑
这里占用较多的都是日志的对象,看了下代码里日志打印的也并不多,也没有打印任何大的对象 而且JVM HeapSize 限制占用并不高,但是POD占用内存已经3G多。于是也查了一圈资料后,发现可能 堆外内存泄漏的问题。
3、内存泄漏
好在是SSO 服务,代码量不大,先利用了下AI 排查了出一处可疑 的地方。
private static String getIp (String Ip) {
//省略前后代码
DbSearcher dbSearcher = extracted();
DataBlock dataBlock = dbSearcher.memorySearch(ip);
//。。。。
}
private static DbSearcher extracted() {
try {
DbConfig config = new DbConfig();
DbSearcher dbSearcher = new DbSearcher(config,IPDBFILEPATH);
return dbSearcher;
} catch (Exception e) {
log.info("创建ip地址搜索器失败[{}]", e);
return null;
}
}
某个接口调用方法获取IP归属地信息 用开源 ip2region 方法,从本地的DB 文件里搜索。 每次请求都创建了新的DBSearch 对象打开这个DB文件,并且最后也没有关闭。
查看DBSearch 源码 发现底层调用的是 NIO下的 RandomAccessFile
编辑
这是一个native 方法,属于GC ROOT 无法被垃圾回收,最终导致内存泄漏。
4、验证
由于第一次排查这种问题,此前对JVM 也并不了解,根据查询的资料验证验证下是否和我理解一致,打算在测试环境测试一下。
4.1 测试前准备
调用前 的内存占用
编辑
为了内看到内存内容提前 将内存地址打印出来
pmap -x 1 > pmap_$(date +"%Y%m%d_%H%M%S").log
4.2 接口调用
这里通过工具调用了200次接口。
同时打印JVM 信息
编辑
表头 含义如下:
-
S0C: Survivor 0区当前容量 (KB) - S1C: Survivor 1区当前容量 (KB)
-
S0U: Survivor 0区已使用 (KB) - S1U: Survivor 1区已使用 (KB)
-
EC: Eden区当前容量 (KB)- EU: Eden区已使用 (KB)
-
OC: Old区当前容量 (KB)- OU: Old区已使用 (KB)
-
MC: Metaspace(元空间)容量 (KB)- MU: Metaspace已使用 (KB)
-
CCSC: 压缩类空间容量 (KB)- CCSU: 压缩类空间已使用 (KB)
-
YGC: 年轻代垃圾回收次数- YGCT: 年轻代垃圾回收消耗时间 (s)
-
FGC: 老年代垃圾回收次数(Full GC)- FGCT: 老年代垃圾回收消耗时间 (s)
-
GCT: 垃圾回收总消耗时间 (s
这里可以看到 老年代 的用量飙升,并且通过FULLGC 也并没有好转。
同时top看到 应用占用的内存已经有 2.5G 编辑
这里也通过了arthas 的memery 打印了内存信息
编辑
可以看到与实际占用的内存还是要有差距,这里应该就是JNI 调用导致的堆外内存泄漏,接口调用的文件是9.5M ,刚好也和这里大小能对的上。
于是现在再通过pmap 打印出当前的内存信息
pmap -x 1 > pmap_$(date +"%Y%m%d_%H%M%S").log
和执行前的文件进行比对
icdiff pmap_20250617_142345.log pmap_20250617_142729.log|less -SR
编辑发现多了很多这些9M左右的内容,随便找了一个通gdb命令获取这内存中的内容
gdb -p 1 -batch -ex "dump memory dump.bin 0x00007f486c000000 0x00007f486c000000+$((9152*1024))" 2>/dev/null
拿到文件后打开虽然里面有很多乱码,但是能显示的部份还是能和那份DB文件对上,于是能确定这些新增的内存里存放的应该都是这份文件了。
** 补充:这里后来为了确认真的无法被GC 回收手动通过jcmd 调用了GC 也只能释放100M左右的内存**
4.3 修改后测试
手动增加close 的代码
finally {
try {
dbSearcher.close();
} catch (IOException e) {
log.info("IPUtils close ERROR ", e);
}
}
再次测试
调用前内存使用量top
编辑调用后的top 如下
编辑
这里内存还是增加了
通过arthas 的内存打印结果如下
编辑
于是我又打印出来了pmap 发现里面还是存在了那份文件。
这就让我比较疑惑,于是我通过手动调用
jcmd <pid> GC.run
发现内存有所下降大概有能降到 但是内存还是偏高了。
(第一次GC 后能降到1G左右,在此调用200次后手动GC 在1.7G ,后面重复操作了两次都会让内存上升100M左右)
不过我这里的修改也不合理,毕竟每次接口都创建一次这个对象,并高的话可能导致频繁GC影响性能,甚至OOM。
于是将DBSearch的创建改成了单例模式创建。
private static final Object lock = new Object();
private static volatile DbSearcher dbSearcher;
private static DbSearcher getDbSearcher() {
if (dbSearcher == null) {
synchronized (lock) {
if (dbSearcher == null) {
try {
DbConfig config = new DbConfig();
dbSearcher = new DbSearcher(config, IP2REGION);
} catch (Exception e) {
log.error("初始化DbSearcher失败", e);
throw new RuntimeException("IP地址库初始化失败", e);
}
}
}
}
return dbSearcher;
}
再次测试后完美解决,高并发下内存也没有飙升。
5、总结
由于之前没有这方面经验,并不清楚还有堆外内存的情况一致从dump 文件看,没发现任何异常。最终虽然解决了问题,但是第一次修改的后内存还是偏高的情况,还是没弄清楚,后面会再找时间专门研究下。