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

# 由于日志是没问题的，这里直接复制上面日志了

[jboss @VM_0_139_centos ~]$ ping 10.0.0.139

PING 10.0.0.139( 10.0.0.139) 56( 84) bytes of data.

64bytes from 10.0.0.139: icmp_seq= 1ttl= 64time= 0.029ms

64bytes from 10.0.0.139: icmp_seq= 2ttl= 64time= 0.041ms

64bytes from 10.0.0.139: icmp_seq= 3ttl= 64time= 0.040ms

64bytes from 10.0.0.139: icmp_seq= 4ttl= 64time= 0.040ms

从ping结果上看，Nginx到渠道系统服务器网络延迟也是没问题的

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

[jboss @VM_10_91_centos tmp]$ curl -w "@curl-time.txt"http: //127.0.0.1:7744/send

success

http: 200

dns: 0.001s

redirect: 0.000s

time_connect: 0.001s

time_appconnect: 0.000s

time_pretransfer: 0.001s

time_starttransfer: 0.073s

size_download: 7bytes

speed_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/send

success

http: 200

dns: 0.001s

redirect: 0.000s

time_connect: 0.001s

time_appconnect: 0.000s

time_pretransfer: 0.001s

time_starttransfer: 0.003s

size_download: 7bytes

speed_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可以帮助你解决：

这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？

我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？

遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？

线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！

是否有一个全局视角来查看系统的运行状况？

有什么办法可以监控到JVM的实时运行状态？

这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？

我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？

遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？

线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！

是否有一个全局视角来查看系统的运行状况？

有什么办法可以监控到JVM的实时运行状态？

上面是Arthas的官方简介，这次我只需要用他的一个小功能 trace。动态计算方法调用路径和时间，这样我就可以定位时间在哪个地方被消耗了。

trace 方法内部调用路径，并输出方法路径上的每个节点上耗时

trace 命令能主动搜索 class-pattern／method-pattern

对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

trace 方法内部调用路径，并输出方法路径上的每个节点上耗时

trace 命令能主动搜索 class-pattern／method-pattern

对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

有了神器，那么该追踪什么方法呢？由于我对Tomcat源码不是很熟，所以只能从spring mvc下手，先来trace一下spring mvc的入口：

[jboss @VM_10_91_centos tmp]$ curl -w "@curl-time.txt"http: //127.0.0.1:7744/send

success

http: 200

dns: 0.001s

redirect: 0.000s

time_connect: 0.001s

time_appconnect: 0.000s

time_pretransfer: 0.001s

time_starttransfer: 0.115s

size_download: 7bytes

speed_download: 60.000B/s

----------

time_total: 0.115s

本次调用，调用端时间花费115ms，但是从arthas trace上看，spring mvc只消耗了18ms，那么剩下的97ms去哪了呢？

本地测试后已经可以排除spring mvc的问题了，最后也是唯一可能出问题的点就是tomcat

可是本人并不熟悉tomcat中的源码，就连请求入口都不清楚，tomcat里需要trace的类都不好找。。。

不过没关系，有神器Arthas，可以通过stack命令来反向查找调用路径，以 org.springframework.web.servlet.DispatcherServlet 作为参数：

stack 输出当前方法被调用的调用路径

很多时候我们都知道一个方法被执行，但这个方法被执行的路径非常多，或者你根本就不知道这个方法是从那里被执行了，此时你需要的是 stack 命令。

”

stack 输出当前方法被调用的调用路径

很多时候我们都知道一个方法被执行，但这个方法被执行的路径非常多，或者你根本就不知道这个方法是从那里被执行了，此时你需要的是 stack 命令。

”

从stack日志上可以很直观的看出DispatchServlet的调用栈，那么这么长的路径，该trace哪个类呢（这里跳过spring mvc中的过滤器的trace过程，实际排查的时候也trace了一遍，但这诡异的时间消耗不是由这里过滤器产生的）？

有一定经验的老司机从名字上大概也能猜出来从哪里下手比较好，那就是 org.apache.coyote.http11.Http11Processor.service ，从名字上看，http1.1处理器，这可能是一个比较好的切入点。下面来trace一下：

日志里有一个129ms的耗时点（时间比没开arthas的时候更长是因为arthas本身带来的性能消耗，所以生产环境小心使用），这个就是要找的问题点。

打问题点找到了，那怎么定位是什么导致的问题呢，又如何解决呢？

继续trace吧，细化到具体的代码块或者内容。trace由于性能考虑，不会展示所有的调用路径，如果调用路径过深，只有手动深入trace，原则就是trace耗时长的那个方法：

一段无聊的手动深入trace之后………………

发现了一个值得暂停思考的点：

+---[min= 0.004452ms,max= 34.479307ms,total= 74.206249ms,count= 31] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry # 117

这行代码加载了31次，一共耗时74ms；从名字上看，应该是tomcat加载jar包时的耗时，那么是加载了31个jar包的耗时，还是加载了jar包内的某些资源31次耗时呢？

TomcatJarInputStream这个类源码的注释写到：

The purpose of thissub- classistoobtainreferencestotheJarEntryobjectsforMETA- INF/ andMETA- INF/ MANIFEST. MFthatareotherwiseswallowedbytheJarInputStreamimplementation.

大概意思也就是，获取jar包内META-INF/，META-INF/MANIFEST的资源，这是一个子类，更多的功能在父类JarInputStream里。

其实看到这里大概也能猜到问题了，tomcat加载jar包内META-INF/，META-INF/MANIFEST的资源导致的耗时，至于为什么连续请求不会耗时，应该是tomcat的缓存机制（下面介绍源码分析）

不着急定位问题，试着通过Arthas最终定位问题细节，继续手动深入trace

[arthas@ 24851]$ trace org.apache.catalina.webresources.TomcatJarInputStream *

Press Q or Ctrl+C to abort.

Affect( class- cnt:1 , method- cnt:4) costin44 ms.

`--- ts= 2019- 09- 1421: 37: 47;thread_name=http-nio- 7744-exec- 5;id= 14;is_daemon= true;priority= 5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@ 20ad9418

`---[ 0.234952ms] org.apache.catalina.webresources.TomcatJarInputStream:createZipEntry

+---[ 0.039455ms] java.util.jar.JarInputStream:createZipEntry # 43

`---[ 0.007827ms] java.lang.String:equals # 44

`---ts= 2019- 09- 1421: 37: 47;thread_name=http-nio- 7744-exec- 5;id= 14;is_daemon= true;priority= 5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@ 20ad9418

`---[ 0.050222ms] org.apache.catalina.webresources.TomcatJarInputStream:createZipEntry

+---[ 0.001889ms] java.util.jar.JarInputStream:createZipEntry # 43

`---[ 0.001643ms] java.lang.String:equals # 46

#这里一共 31个trace日志，删减了剩下的

从方法名上看，还是加载资源之类的意思。都已经到jdk源码了，这时候来看一下 TomcatJarInputStream 这个类的源码:

/**

* Creates a new JarEntry (ZipEntry) for the

* specified JAR file entry name. The manifest attributes of

* the specified JAR file entry name will be copied to the new

* JarEntry.

*

* @paramname the name of the JAR/ZIP file entry

* @returnthe JarEntry object just created

*/

protectedZipEntry createZipEntry(String name){

JarEntry e = newJarEntry(name);

if(man != null) {

e.attr = man.getAttributes(name);

}

returne;

}

这个 createZipEntry 有个name参数，从注释上看，是jar/zip文件名，如果能得到文件名这种关键信息，就可以直接定位问题了；还是通过Arthas，使用watch命令，动态监测方法调用数据

watch方法执行数据观测

让你能方便的观察到指定方法的调用情况。能观察到的范围为：返回值、抛出异常、入参，通过编写 OGNL 表达式进行对应变量的查看。

”

让你能方便的观察到指定方法的调用情况。能观察到的范围为：返回值、抛出异常、入参，通过编写 OGNL 表达式进行对应变量的查看。

”

watch 该方法的入参

这下直接看到了具体加载的资源名，这么熟悉的名字：swagger-ui，一个国外的rest接口文档工具，又有国内开发者基于swagger-ui做了一套spring mvc的集成工具，通过注解就可以自动生成swagger-ui需要的接口定义json文件，用起来还比较方便，就是侵入性较强。

删除swagger的jar包后问题，诡异的70+ms就消失了

< dependency>

< groupId> io.springfox

< artifactId> springfox-swagger2

< version> 2.9.2

< dependency>

< groupId> io.springfox

< artifactId> springfox-swagger-ui

< version> 2.9.2

那么为什么swagger会导致请求耗时呢，为什么每次请求偶读会加载swagger内部的静态资源呢？

其实这是tomcat-embed的一个bug吧，下面详细介绍一下该Bug

Tomcat embed Bug分析&解决

源码分析过程实在太漫长，而且也不是本文的重点，所以就不介绍了， 下面直接介绍下分析结果

顺便贴一张tomcat处理请求的核心类图

为什么每次请求会加载Jar包内的静态资源

关键在于 org.apache.catalina.mapper.Mapper#internalMapWrapper 这个方法，该版本下处理请求的方式有问题，导致每次都校验静态资源。

为什么连续请求不会出现问题

因为Tomcat对于这种静态资源的解析是有缓存的，优先从缓存查找，缓存过期后再重新解析。具体参考 org.apache.catalina.webresources.Cache ，默认过期时间ttl是5000ms。

为什么本地不会复现

其实确切的说，是通过spring-boot打包插件后不能复现。由于启动方式的不同，tomcat使用了不同的类去处理静态资源，所以没问题

如何解决

升级tomcat-embed版本即可

当前出现Bug的版本为：

spring-boot:2.0.2.RELEASE，内置的tomcat embed版本为8.5.31

升级tomcat embed版本至8.5.40+即可解决此问题，新版本已经修复了

通过替换springboot pom properties方式

如果项目是maven是继承的springboot，即parent配置为springboot的，或者dependencyManagement中import spring boot包的

< parent>

< groupId> org.springframework.boot

< artifactId> spring-boot-starter-parent

< version> 2.0.2.RELEASE

< relativePath/>

pom中直接覆盖properties即可：

< properties>

< tomcat.version> 8.5.40

升级spring boot版本

springboot 2.1.0.RELEASE中的tomcat embed版本已经大于8.5.31了，所以直接将springboot升级至该版本及以上版本就可以解决此问题

全文完，感谢你的耐心阅读。如果你还想看到我的文章，请一定给本文“在看”、 “点赞”，新文章推送才会第一时间出现在你的微信里。

- END -

热门推荐：

字节面试：说说零拷贝，成功上岸！

不要把公司当成家，被通知裁员时会变得不幸...

公务员工作8年升职到正科，发完工资后感叹：公积金首次过万

字节面试：说说零拷贝，成功上岸！

不要把公司当成家，被通知裁员时会变得不幸...

公务员工作8年升职到正科，发完工资后感叹：公积金首次过万

PS：如果觉得我的分享不错，欢迎大家随手点赞、转发、在看。返回搜狐，查看更多