项目使用了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放进缓存, 子服务自然识别不到了.
那么测试环境的类是什么样的呢?为什么注解能识别到呢? 使用神器Arthas试试.
使用Arthas
-
首先使用sc命令查看jvm里加载的类信息
image.png
发现有个类名带有Proxy, 是JDK代理类, 这个差异很可能就是造成测试环境bug没复现的原因. 而且有好多个在开发环境正常的类测试环境也变成代理类了. 应该是有个地方统一给这些类做了增强. 于是现在问题就变成了 哪里使用了cglib代理了这些类, 而且只在测试环境才使用了呢? 我自己项目里的代码里是没这样用的, 可能是在某个引用的包里. 继续挖.
-
这次使用trace命令查看方法的调用链, 想看看调用链里有没有发现
image.png
输入命令后, 发送一笔请求, 发现只有各个节点的耗时时长, 没有别的信息了. 官方文档这个命令的说明是方法内部调用路径,并输出方法路径上的每个节点上耗时, 看来只能看到方法内部的调用链, 方法外的看不到, 而我要找的是哪里增强了这个方法.
-
接下去尝试使用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 -
用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
小结
以前只了解过两种动态代理的实现机制及区别, 没感受过这种区别对系统运行造成的影响. 就这个bug来说, 是代理类的父类不同造成的.
以后如果遇到这类问题也多了个debug思路.
Arthas真香. 以前debug时用的笨方法都可以用它代替. 比如定位接口耗时长问题, 不用在代码里一段段打印耗时日志再重新部署了,
一行trace命令就可以打印出各个链路的耗时; 比如不确定部署的代码是不是刚才更新的, 可以使用jad反编译查看变更的类.
带有@Async @Schedule @Transation 等注解的方法最好分类放到单独的类里, 比如专门的异步任务类, 定时任务类等.不仅能避免代理方面的问题, 也能使代码结构更清晰整洁.
