【Arthas】定位线上问题

项目使用了MumbleSDK 2.x, rmb请求先到一个Dispatcher类, 然后Dispatcher根据请求参数里的bizServiceId把请求分发到不同的子服务接口. 各个子服务接口上有个@MumbleMessageService标注着自己对应的bizServiceId.

上个月有个一次性的补数需求, 图方便我就直接在子服务的类里用@Async写了个异步方法, 分发服务Dispatcher就识别不到@MumbleMessageService注解找不到子服务了. 根据组内其他小伙伴的经验, 是因为这个类被spring代理了导致的. 后来把异步方法抽到单独的类实现, 服务就正常了.
但这个bug在测试环境没有复现过, 如果是代理问题,那么在什么环境都应该复现才对, 这篇文章就是寻找测试环境没复现的原因, 以及从源码层面上分析为什么@Async会导致找不到子服务的注解.

本地调试

开发环境运行后bug复现了, 看了Dispatcher分发服务的源码, 原理是系统启动时扫描所有继承了MumbleBaseService的类, 然后遍历实现类以及父类里的方法是否带有@MumbleMessageService, 如果有就放在缓存里, 请求过来时就从缓存里取出对应的服务.
在扫描结束的位置加了断点, 可以看到出问题的那个类由于有个方法用了@Async, 类名带有$Proxy, 是个JDK动态代理类. 而JDK动态代理类和它的父类java.lang.reflect.Proxy 方法上都没有@MumbleMessageService, 所以不会被Dispatcher放进缓存, 子服务自然识别不到了.

image.png

那么测试环境的类是什么样的呢?为什么注解能识别到呢? 使用神器Arthas试试.

使用Arthas

1. 首先使用sc命令查看jvm里加载的类信息
   

   image.png
   发现有个类名带有 Proxy, 是JDK代理类, 这个差异很可能就是造成测试环境bug没复现的原因. 而且有好多个在开发环境正常的类测试环境也变成代理类了. 应该是有个地方统一给这些类做了增强. 于是现在问题就变成了 哪里使用了cglib代理了这些类, 而且只在测试环境才使用了呢? 我自己项目里的代码里是没这样用的, 可能是在某个引用的包里. 继续挖.

2. 这次使用trace命令查看方法的调用链, 想看看调用链里有没有发现

   
   image.png
   

   输入命令后, 发送一笔请求, 发现只有各个节点的耗时时长, 没有别的信息了. 官方文档这个命令的说明是方法内部调用路径,并输出方法路径上的每个节点上耗时, 看来只能看到方法内部的调用链, 方法外的看不到, 而我要找的是哪里增强了这个方法.

3. 接下去尝试使用stack命令查询方法被调用的调用路径
   下图是发送请求后stack命令打印出来的东西, 出现了一个mumbleSDK里的类, 名字看起来就是使用了AOP切面

   
   image.png
   

   找到这个类源码, 就是它了! MumbleSDK里的dao,rmb调用耗时监控组件, 给项目里service目录下的类都做了cglib代理, 而且只有测试环境满足了@Conditional里的条件所以开启了.

   
   image.png
   让我们验证下, 在项目的配置文件里加上 mumble.monitor.web.enabled=false 关闭这个监控服务. 部署到测试环境后bug终于重现了. 再次使用sc查看, 之前的cglib代理类已经变成JDK代理了
   image.png

4. 用jad命令反编译两种不同的代理类
   下图是cglib的, 可以看到继承的父类是原来的类. 再复习下MumbleSDK Dispatcher识别服务的原理: 遍历实现类以及父类的方法扫描@MumbleMessageService注解. 所以可以识别到方法上的@MumbleMessageService并把子服务加进缓存. 这就是一开始测试环境能识别到子服务的原因.

   
   image.png
   

   下图是jdk代理类, 父类是Proxy, 方法上没有@MumbleMessageService. 也就会出现找不到子服务的问题了.

   
   image.png
   所以这个bug的根本原因是不同类型的动态代理的实现差异导致的, 而不是一开始认为的单纯是因为被代理了.
   下图是@EnableAsync里的代码, 默认是jdk代理.
   image.png
   

   回到本地开发环境, 把@EnableAsync改成 @EnableAsync(proxyTargetClass = true), 强制使用cglib代理. 重启服务, 开发环境的服务也正常了.
   但是, 为了能乱放@Async而去改spring的默认代理配置是不合理的, 还是要把@Async方法独立出去.

Arthas Idea插件

命令或类名太长记不得可以安装使用Aethas的idea插件,如下图,在方法上右键选中相应的命令, 就可以把命令复制到剪贴板, 直接去终端粘贴使用就行了. 比如下图粘贴的结果是
stack cn.webank.pmbank.cp.ocr.service.impl.OcrCorePojoService DoCommonOcr -n 5

image.png

小结

以前只了解过两种动态代理的实现机制及区别, 没感受过这种区别对系统运行造成的影响. 就这个bug来说, 是代理类的父类不同造成的.
以后如果遇到这类问题也多了个debug思路.
Arthas真香. 以前debug时用的笨方法都可以用它代替. 比如定位接口耗时长问题, 不用在代码里一段段打印耗时日志再重新部署了,
一行trace命令就可以打印出各个链路的耗时; 比如不确定部署的代码是不是刚才更新的, 可以使用jad反编译查看变更的类.
带有@Async @Schedule @Transation 等注解的方法最好分类放到单独的类里, 比如专门的异步任务类, 定时任务类等.不仅能避免代理方面的问题, 也能使代码结构更清晰整洁.