凛冬将至,北京的天气愈发寒冷,世间的一切如四季一般周而复始,相似的问题难免再次出现。几个月前发过一篇帮兄弟部门排查 JVM 僵死的文章《谜!JVM为何僵死》,最近自己也遇到了一个 JVM 僵死的问题,这个案例很有意义,特地再发一文,望诸位读完能有些收获。
随着业务的发展,相关系统的规模越来越大,系统之间的关系随业务的变化、组织的调整、人员的流动、新技术的引入等原因逐渐错综复杂,各式各样的挑战也逐渐凸显:
历史负担很重,能否低成本的落地微服务架构?
业务极端复杂,服务的边界划分是否合理?
系统依赖繁琐,如何理清整体拓扑、如何进行监控报警、如何平滑上线?
为了解决这一系列的相关问题,我们业余自研了一套服务化基础设施
dkimi,自动梳理系统拓扑、自动提供各种监控统计、智能量化系统结构的合理度与复杂度、全链路流量收集与回放测试……我们希望以一种完全业务无侵入的方式赋予我们的业务系统统一的系统性功能、赋予我们的业务系统服务自治的能力,让业务系统更加智能。
DKIMI - Do Keep It More Intelligent
从技术上来讲,dkimi 本质上是一个 Java Agent, 基于 java.lang.instrument ,通过字节码修改提供各种增强功能。dkimi 跟业务逻辑运行在同一 JVM 进程中,在任何情况下都需要保证对业务不产生干扰,所以我们设计了 独立的 ClassLoader 来加载自身的类,期望与业务充分隔离,尽可能避免出现字节码冲突。
期望很美好,现实很残酷。这次遇到的问题就跟 dkimi 里的 ClassLoader 有关,跟 Tomcat 的 WebappClassLoader 实现有关,也跟 JVM 的类加载机制有关。
现象
过去一年里,dkimi 在测试环境下大放异彩,也逐渐开始推广到生产环境。在逐步上线了几十个业务系统、几百个实例并长时间观察稳定之后我们将 dkimi 推广到了最核心的业务系统之一,下称 AF。
AF 是一个基于 Tomcat 容器部署的 web 应用,在生产环境部署了 6 个实例。最核心的业务系统,逻辑自然十分复杂,启动速度也比较慢。相信大家都知道 tomcat 容器启动时会先监听端口,接收请求,但是在应用启动完成之前请求会被 hold 住,无法实际处理。当启动时间较长时,监控系统会检测到 499 错误。
某一天上线时发现 AF 的其中 1 个实例在 dkimi 输出已经实际启动完成后仍然无响应,access log 无输出,呈僵死状。这是怎么了?为什么其他系统没问题?为什么同样的系统其他实例没问题?是上线的新功能有漏洞吗?
胡乱猜测与手足无措都无济于事,面对这样的问题,还是要祭起 jstack 这柄利器。
现场
通过 jstack -l 得到如下信息,发现存在死锁:
相信大家都知道,死锁的一般原因是: 存在嵌套加锁,且有至少两个逻辑加锁的顺序不一致。
1.我们来看看这两个线程的调用栈是不是存在这样的情况。"catalina-exec-235"的调用栈如下,确实先锁了 WebappClassLoader,在等待 DkimiPluginClassLoader 的锁:
2."catalina-exec-96"的调用栈如下,只看到在等待 WebappClassLoader 的锁,并没有看到对 DkimiPluginClassLoader 加锁,为什么死锁了呢?
分析
如上一篇文章所说,处理线上问题,最要紧的一定是先尽快恢复服务,减少业务损失。 运维同学当机立断,在收集完相关现场之后,即刻先下掉了 dkimi。咱们接下来分析原因。我们来看看 dkimi 里自定义的 ClassLoader 的实现, 简化如下:
1.锁住自己 this,也就是 DkimiPluginClassLoader,尝试加载自身的类。
2.找不到或者是其他类时,锁住 parent,当下也就是 WebappClassLoader,委派给 parent 去加载。
并没有看到这两段逻辑存在嵌套加锁的情况,为什么线程"catalina-exec-96"在尝试抢占 parent(WebappClassLoader)时还锁着 this(DkimiPluginClassLoader)呢???
这绝不单单是 Java 语言层面的原因,是不是下图红框中的调用逻辑里潜藏着不为人知的秘密?
先看看 DubboConsumerSerializer.java 的第 43 行是什么:
很普通的一行代码,目测是触发了加载 java.lang.reflect.Method 类。 再看看 jstack -m 的输出,看看这之间发生了什么:
可以看到,在真正调用到 ClassLoader.loadClass 之前,还有很深的本地方法栈(也就是 JVM 自身的逻辑)。但是这个调用栈是什么意思,为什么看起来跟乱码一样?是不是在这些调用里锁住了 DkimiPluginClassLoader?
简单地解析一下这些看起来像乱码一样的调用是什么意思,以其中一行为例:
了解编译器的同学应该知道,编译器中有一种技术叫做名字修饰,用于解决由于程序实体的名字必须唯一而导致的问题的一种技术。上面的这一行实际上就是被 GCC 修饰后的方法调用,简单解析如下:
到此,这些调用栈我们也能读懂了,这一行的完整含义是:
通过参考 openjdk 相关的源码,确实证明了我们的推断,具体的过程无非是沿着调用逻辑读了一遍。我们直接来看看相关的代码,加锁的逻辑出现在上图中背景飘绿的方法调用里,逻辑很清晰,注释很完整,这里就不展开解释了。
原因
为什么死锁?
因为 WebappClassLoader 的实现里会锁住自己,当加载的类需要被 dkimi 增强时,又嵌套调用到了 DkimiPluginClassLoader;
同时 JVM 类的懒加载机制,会使用当前类的加载器,去加载尚未加载的类,加载的过程中会先锁住当前的类加载器,也就是 DkimiPluginClassLoader
为什么只有一个实例发生?
通过分析我们知道,这个问题是一直存在的,但因为死锁跟时序有关,并不容易复现,之所以只有一个实例发生,我们推测可能是由于这个实例所在的物理机器配置较低,实际运行较慢,同时核心业务的并发量较大,加大了问题出现的概率。 经过与运维同学的确认,发现确实如我们的推测一致。
解决
知道了原因之后,解决方案的原理也很简单,无非是要么保证加锁顺序一致,要么不要出现嵌套加锁。
具体可以实施的方法也很多,目前我们先采取了将 DkimiPluginClassLoader 注册为 ParallelCapable 的方式去掉了锁的嵌套。(特别注意:这种方案只在 java7 之后有效)。
后记与启示
从发现无响应到收集完现场并重启花费了 1-2 分钟的时间,造成了一些 499 错误,同时当天业务系统也因为上线启动慢等原因引起了一些 499 错误,因此还与相关业务团队发生了些许误会,还好大家也都很 nice,都是希望系统能更加稳定高效。感谢相关小伙伴的理解与支持。
1.期望越美好,付出的努力就必须越大,无论是技术上的,还是沟通上的。
2.大胆猜测、小心求证,问题总能找到原因,真相只有一个。
3.dkimi 提供主动暴露服务是否可用的状态信息,期待运维同学基于此功能的平滑上线、实时负载均衡早日上线,彻底解决实例启动过程中服务不可用导致的相关问题。
本文转载自公众号贝壳产品技术(ID:gh_9afeb423f390)。
原文链接:
https://mp.weixin.qq.com/s/c9RxJqLF8aaIyjA4aE5yiw
评论