Java方法超时定位, Arthas性能诊断

问题来源

最近在项目的业务逻辑接口编写过程中，其中一个分页接口的调用时长高达8s，这显然是不被允许的。排查业务逻辑过程中，发现有2次调用其他服务的接口（微服务调用）34次查询mysql操作（在循环里），显然大概率是由于循环中查询数据库造成了巨大负担。
即便如此，我在主观意识上感觉接口耗时也不会这么长，整个Java分页接口大概处理了40条数据。

redis代替mysql尝试

分析了一下原因，又搂了一眼逻辑，认为从mysql查询的用户数据是不经常修改且查询频率适中，所以觉得在中间再加一道redis缓存，这下问题应该解决了。

还是8秒？

然而用redis替代之后，整个接口的耗时却几乎不为所动，难道缓存的效率不比mysql高？
又经过一段时间的思考，我觉得深究一下，到底是接口中的哪个类的哪个方法造成了高耗时，请教过周围的大佬之后，大佬给推荐了一个很强大的JVM性能诊断工具Arthas

Arthas安装与入门(超容易上手)

安装Arthas的jar包（提前建好目录）

curl -0 https://arthas.aliyun.com/arthas-boot.jar --output arthas-boot.jar
1

安装好之后,可以看到arthas-boot.jar已经在当前目录了，可以使用java -jar命令运行jar包

java -jar arthas-boot.jar
1

Arthus服务接口监听

命令行中的[1], [2], [3], [4]就是Arthas启动所检测到的本机正在运行的JVM程序，选中序号就可以进入到我们所希望监听的程序中去。
出现如图所示的信息，就说明此时启动的arthas已经成功监听的服务，那如何打印方法调用时间呢？
执行命令:

trace 全限定类型 方法名
# 如 
# trace com.it.boot.service.impl.LoginServiceImpl login
1
2
3

出现如下所示，即为接口监听成功, 我们在调用接口之后，arthas会把方法的调用时间打印到控制台，前提是执行的接口一点得调用到arthas监听的方法。

Affect(class count: 1 , method count: 1) cost in 146 ms, listenerId: 1
1

原因所在

经过上述的监听并执行后，将arthus的打印结果截图如下：

很清晰可以看到，绝大多数的耗时都集中在97.29%所在的方法上（1200ms是优化后的），而关于如何优化就是根据自己服务的特点，逐步分析。