用 Arthas 定位 Spring Boot 接口的超时问题，让应用起飞 _Spring

一、背景公司有个渠道系统，专门对接三方渠道使用，没有什么业务逻辑，主要是转换报文和参数校验之类的工作，起着一个承上启下的作用。
最近在优化接口的响应时间，优化了代码之后，但是时间还是达不到要求；有一个诡异的100ms左右的耗时问题，在接口中打印了请求处理时间后，和调用方的响应时间还有差了100ms左右。比如程序里记录150ms，但是调用方等待时间却为250ms左右。
下面记录下当时详细的定位&解决流程（其实解决很简单，关键在于怎么定位并找到解决问题的方法）。

文章插图
二、定位过程1.分析代码渠道系统是一个常见的spring-boot web工程，使用了集成的Tomcat 。分析了代码之后，发现并没有特殊的地方，没有特殊的过滤器或者拦截器，所以初步排除是业务代码问题。
2.分析调用流程出现这个问题之后，首先确认了下接口的调用流程。由于是内部测试，所以调用流程较少。
Nginx -反向代理-> 渠道系统
公司是云服务器，网络走的也是云的内网。由于不明确问题的原因，所以用排除法，首先确认服务器网络是否有问题。
先确认发送端到Nginx Host是否有问题：

[jboss@VM_0_139_centos ~]$ ping 10.0.0.139PING 10.0.0.139 (10.0.0.139) 56(84) bytes of data.64 bytes from 10.0.0.139: icmp_seq=1 ttl=64 time=0.029 ms64 bytes from 10.0.0.139: icmp_seq=2 ttl=64 time=0.041 ms64 bytes from 10.0.0.139: icmp_seq=3 ttl=64 time=0.040 ms64 bytes from 10.0.0.139: icmp_seq=4 ttl=64 time=0.040 ms

从ping结果上看，发送端到Nginx主机的延迟是无问题的，接下来查看Nginx到渠道系统的网络。

# 由于日志是没问题的，这里直接复制上面日志了[jboss@VM_0_139_centos ~]$ ping 10.0.0.139PING 10.0.0.139 (10.0.0.139) 56(84) bytes of data.64 bytes from 10.0.0.139: icmp_seq=1 ttl=64 time=0.029 ms64 bytes from 10.0.0.139: icmp_seq=2 ttl=64 time=0.041 ms64 bytes from 10.0.0.139: icmp_seq=3 ttl=64 time=0.040 ms64 bytes from 10.0.0.139: icmp_seq=4 ttl=64 time=0.040 ms

从ping结果上看，Nginx到渠道系统服务器网络延迟也是没问题的。
既然网络看似没问题，那么可以继续排除法，砍掉Nginx，客户端直接再渠道系统的服务器上，通过回环地址（localhost）直连，避免经过网卡/DNS，缩小问题范围看看能否复现（这个应用和地址是我后期模拟的，测试的是一个空接口）：

[jboss@VM_10_91_centos tmp]$ curl -w "@curl-time.txt" http://127.0.0.1:7744/sendsuccesshttp: 200dns: 0.001sredirect: 0.000stime_connect: 0.001stime_Appconnect: 0.000stime_pretransfer: 0.001stime_starttransfer: 0.073ssize_download: 7bytesspeed_download: 95.000B/s----------time_total: 0.073s 请求总耗时

从curl日志上看，通过回环地址调用一个空接口耗时也有73ms 。这就奇怪了，跳过了中间所有调用节点（包括过滤器&拦截器之类），直接请求应用一个空接口，都有73ms的耗时，再请求一次看看：

[jboss@VM_10_91_centos tmp]$ curl -w "@curl-time.txt" http://127.0.0.1:7744/sendsuccesshttp: 200dns: 0.001sredirect: 0.000stime_connect: 0.001stime_appconnect: 0.000stime_pretransfer: 0.001stime_starttransfer: 0.003ssize_download: 7bytesspeed_download: 2611.000B/s----------time_total: 0.003s

更奇怪的是，第二次请求耗时就正常了，变成了3ms 。经查阅资料， linux curl是默认开启http keep-alive的。就算不开启keep-alive，每次重新handshake，也不至于需要70ms 。
经过不断分析测试发现，连续请求的话时间就会很短，每次请求只需要几毫秒，但是如果隔一段时间再请求，就会花费70ms以上。
从这个现象猜想，可能是某些缓存机制导致的，连续请求因为有缓存，所以速度快，时间长缓存失效后导致时间长。
那么这个问题点到底在哪一层呢？tomcat层还是spring-webmvc呢？
光猜想定位不了问题，还是得实际测试一下，把渠道系统的代码放到本地ide里启动测试能否复现
但是导入本地Ide后，在Ide中启动后并不能复现问题，并没有70+ms的延迟问题。这下头疼了，本地无法复现，不能Debug，由于问题点不在业务代码，也不能通过加日志的方式来Debug
这时候可以祭出神器Arthas了。
三、Arthas分析问题Arthas 是Alibaba开源的JAVA诊断工具，深受开发者喜爱。当你遇到以下类似问题而束手无策时，Arthas可以帮助你解决：