使用Arthas定位问题

功能概述

首先，Arthas的常用功能大概有以下几个：

• 解决依赖冲突

sc命令：模糊查看当前 JVM 中是否加载了包含关键字的类，以及获取其完全名称。 sc -d 关键字
注意使用 sc -d 命令，获取

classLoaderHash命令：通过 classloader 查看 class 文件来自哪个 jar 包 注意 classloader -c
后面的值填上面获取到的 classLoaderHash值

• 查看线上运行的代码源码，是否是预期的（确认代码是否提交，分支是否正确）

jad --source-only：可以查看源代码。

watch命令：查看方法调用情况。后面跟上完全类名和方法名，以及一个 OGNL的表达式，-f 表示不论正常返回还是异常返回都进行观察，-x 表示输出结果的属性遍历深度，默认为 1，建议无脑写 4就行，最大的遍历深度，再大就不支持了

tt命令：观测方法调用情况，tt命令可以查看「多次调用」并选择其中一个进行观测，但是如果输出结果是多层嵌套就没办法看了，而 watch 可以查看「多层嵌套」的结果。

这两个命令都是用来查看方法调用过程的，不同的是 watch 命令是调用一次打印一次方法的调用情况，而 tt 命令可以先生成一个不断增加的调用列表，然后指定其中某一项进行观测。

• 热启动（类似JRebel）

redefine 命令：「热替换」线上的代码，注意应用重启之后会失效，这在某些紧急情况下会有奇效。
比如说我们修改一下方法体里面的代码，加了一行日志打印

• 看程序运行时的整体情况

dashboard命令：可以查看当前系统的实时数据面板，当运行在Ali-tomcat时，会显示当前tomcat的实时信息，如HTTP请求的qps, rt, 错误数,线程池信息，内存使用情况，系统参数等等。

• 查看程序运行时的jvm状态

jvm 命令：可以查看 JVM 的实时运行状态。

• 定位应用运行中的热点分析系统瓶颈

profiler 命令：支持生成应用热点的火焰图。本质上是通过不断的采样，然后把收集到的采样结果生成火焰图。

应用实例

背景

项目使用了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

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

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

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

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

3. 接下去尝试使用stack命令查询方法被调用的调用路径

下图是发送请求后stack命令打印出来的东西, 出现了一个mumbleSDK里的类, 名字看起来就是使用了AOP切面

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

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

4. 用jad命令反编译两种不同的代理类

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

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

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

回到本地开发环境, 把@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 等注解的方法最好分类放到单独的类里, 比如专门的异步任务类, 定时任务类等.不仅能避免代理方面的问题, 也能使代码结构更清晰整洁.