现象
6.21 9:20 – 10:00 服务频繁CMS Major GC,半小时100+次
处理
紧急重启服务节点,留下一个节点保留现场观察定位问题。服务恢复正常。
定位
一小时内仅有十多个请求大于1s,且非业务高峰期,不存在大量请求;
另外观察该服务30天内 gc 情况,很明显出现内存泄露,每次 Major GC后仍然存在大量内存占用,并且随着时间一直在堆积,直到疯狂 GC 也无济于事,当前 CPU Idle掉到 70%
分析泄露内存实例
jmap -dump:format=b,file=PID.dump PID
推荐通过eclipse MAT打开(新版MAT依赖最新jdk,老版本MAT各种问题,打不开dump文件,dump 文件太大得修改 MAT 配置,增加 Xmx)
尝试过Idea内置 Profiler,可以看到对象,但看不到对象属性的内容;试过 jvisualvm,计算实例保留大小太慢,也可能是版本太低。(shallow size:对象自身占用空间大小,不包含内部引用对象 retained size: 该对象所占空间的大小+直接引用或者间接引用的对象)
TraceSegment 129个,占用 2g ,继续查看其他对象
TraceSegmentRef 共 200W+ 个,占用 1.6G
查看依赖的引用
TraceSegment存在TraceSegmentRef 引用 *List*<*TraceSegmentRef*> refs
类型为 LinkedList
观察到 TraceSegmentRef 内部都是基本类型
确定是该对象导致内存泄露
搜索到 Github 存在对应 issue
https://github.com/apache/skywalking/issues/6703
根因
SW 通过 Segment 维护全链路追踪数据,利用在各组件打点,通过动态修改字节码的方式,以方法拦截的形式传递 span
各组件的插件在 apm-sniffer 包下的 *-plugin 中,以方法打点为例,通过实现 InstanceMethodsAroundInterceptor 的 beforeMethod 及 afterMethod 完成 trace及相关信息的获取。
伪代码:
// called before target method invocation.
beforeMethod() {
ContextManager.createExitSpan() // setThreadLocal
}
// called after target method invocation. Even method's invocation triggers an exception.
afterMethod() {
// 报错
ContextManager.stopSpan() // remove Threadlocal
}
// called when occur exception.
handleMethodException(){
// 一般插件是记录日志即可
log()
}
正常情况下createExitSpan
和stopSpan
调用次数应该保持一致或者 stop 次数大于 create,才能保证 threadLocal 被释放
该项目使用的低版本 es client 导致 agent 调用 stopSpan 前发生异常
且处理请求的是 dubbo 线程池,线程不会释放
导致 threadLocal 中的 span 不断在 Segment 的 refs 中 add,产生了内存泄露
解决
升级 sw,新版本中 es plugin 兼容了低版本,总会调用 stopSpan, 清理 threadlocal。
在线程池场景下(例如 tomcat、dubbo 等),threadlocal 内存泄露是很容易发生的。使用完ThreadLocal之后,需要及时 remove,养成良好的编程习惯。