SpringBoot接口频繁超时，长时间找不到原因，我用 Arthas 定位到了 _SpringBoot

文章插图

文章插图
2020年JAVA原创面试题库连载中
【000期】Java最全面试题库思维导图
【020期】JavaSE系列面试题汇总（共18篇）
【028期】JavaWeb系列面试题汇总（共10篇）
【042期】JavaEE系列面试题汇总（共13篇）
【049期】数据库系列面试题汇总（共6篇）
【053期】中间件系列面试题汇总（共3篇）
【065期】数据结构与算法面试题汇总（共11篇）
【076期】分布式面试题汇总（共10篇）
【077期】综合面试题系列（一）
【078期】综合面试题系列（二）
【079期】综合面试题系列（三）
【080期】综合面试题系列（四）
【081期】综合面试题系列（五）
【082期】综合面试题系列（六）
【083期】综合面试题系列（七）
【084期】综合面试题系列（八）
【085期】综合面试题系列（九）
【086期】综合面试题系列（十）
【087期】综合面试题系列（十一）
【088期】综合面试题系列（十二）
【089期】综合面试题系列（十三）
更多内容，点击上面蓝字查看

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

定位过程分析代码渠道系统是一个常见的spring-boot web工程，使用了集成的Tomcat 。分析了代码之后，发现并没有特殊的地方，没有特殊的过滤器或者拦截器，所以初步排除是业务代码问题

分析调用流程出现这个问题之后，首先确认了下接口的调用流程。由于是内部测试，所以调用流程较少。
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 。