服务内存泄露问题排查记录

分析一次服务内存泄露问题,并给出解决方案。

最后修改于:

背景

staging 环境,某个车联网服务内存出现了内存泄露,相关同学在 06-14 及 06-15 两天分别采集了两个 dump 文件,以下简单记录分析过程。

内存泄露最常用的排查工具是 Eclipse Memory Analyzer (MAT),使用 MAT 打开两个 dump 文件。

首先看 Leak Suspects

疑点一:JarFile

org.springframework.boot.loader.jar.JarFile 是 Spring Boot 的类加载器,用于加载 jar 包。

猜测此问题与 Druid issue-3808 类似:

  • 所有 jar 包被加载的次数几乎相同;
  • 内存 dump 中相关对象的数量只有几千个,和请求量无关,更像是某些定时任务在做类加载:
    • 06-14 的 dump 中加载次数约为 3250;
    • 06-15 的 dump 中加载次数约为 1260; image1 image2 image3

可以通过升级或降级 mysql-connector-java 版本进行验证。

疑点二:LockPubSub

org.redisson.pubsub.LockPubSub 是 Redisson 的分布式锁实现,用于分布式锁的订阅和消息通知:加锁对象如果已经被锁定需要等待的时候,通过 pubsub 订阅消息注册一个 listener 来等待锁资源

分析 06-14 的内存 dump,发现 key 7e5axxxc00:gateway:xx:zz:msg:task:lock:c53fxxxaa13a 的 listeners 达到 33206 个,内存占用达到 1.32 GB

此问题与 redisson-issues-3577有些相似,但我在日志中没有找到这个服务锁的 timeout 日志(可能因为业务代码没打印),而只有获取锁失败的日志。

另外,业务日志中只有释放锁的日志,而没有加锁的日志(也可能因为业务代码没打印)。
image4 image5 image6

进一步分析

1、对内存泄露部分的 char 数组进行聚合的结果(2.12 GB 的内存泄露,日志信息 1.66GB,占比接近 80%): image7

2、其中一个 char 数组到 gc roots 的路径: image8 这也是内存泄露的路径:OpenTelemetry 在做链路追踪时,会将一次 gRPC、HTTP 调用或 MQ 消费过程中的 Metrics 以及日志信息都放到它的 Context 对象中,这次调用或消费不结束,这些内存就会被引用而释放;业务使用分布式锁的方式可能存在问题,导致很多请求无法结束,大量对象存活无法释放。

3、以下为该服务打印日志的频率监控—-每分钟几千条日志。 image9

4、另外通过Kibana 查询发现,有很多动辄几十 KB 的业务日志(敏感数据就不贴图了)。 5、服务的 GC 信息 image10 image11

综合上述信息,可以确定服务内存泄露,高概率是大日志导致的。

解决方法

  • 升级或降级 mysql-connector-java 版本
  • 避免大日志

参考资料

Licensed under CC BY-NC-SA 4.0
最后更新于 2024/12/20 11:46 CST
本文总阅读量 次 本文总访客量 人 本站总访问量 次 本站总访客数
发表了20篇文章 · 总计32.36k字
本博客已稳定运行
使用 Hugo 构建
主题 StackJimmy 设计