使用arthas排查tomcat异常

背景

前不久上线了一个新服务，是和操作redis相关的业务，正常来说请求的平均响应时间应该小于5ms，99分位线正常也应该在10ms以内。但是上线后通过监控发现存在个别周期性响应时间超过100ms的请求，通过监控平台发现请求在Tomcat Servlet Process阶段时出现了超过100ms的Gap，怀疑是某些东西影响了tomcat导致的，所以想通过arthas追踪发现出现问题的请求。

Arthas

arthas是阿里开源的一个线上诊断工具，能够通过一些方法追踪线上调用，用于诊断一些不方便排查的线上问题。Arthas增强功能的核心是Enhancer和AdviceWeaver这两个类，对方法进行Aop织入，达到watch，trace等效果。

不过今天的主角不是arthas的实现，而是对他的使用。所以介绍的重点也是放在常用的命令而不是实现方式。

• stack

这个方法用于输出当前方法被调用的调用路径

• trace

trace 命令能主动搜索 class-pattern／method-pattern 对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。不过虽然trace能方便的帮助你定位和发现因RT 高而导致的性能问题缺陷，但其每次只能跟踪一级方法的调用链路。这也是使用arthas排查问题最繁琐的地方，如果对这件事没有概念，在下文会有所感知的。

• watch

watch让你能方便地观察到指定方法的调用情况。能观察到的范围为：返回值、抛出异常、入参

使用过程

启动

首先要在服务器上安装arthas，嫌麻烦的同学可以交给摊主（运维）来处理。

使用命令 java -jar arthas/arthas-boot.jar 来启动arthas，之后选择想要监控的进程就好了

排查阶段

这个问题能用arthas顺利解决我个人觉得还有一个比较重要的前提，就是能在测试环境下稳定复现。因为会周期性的出现，而只要我能够一直发送请求就必然会复现问题，所以才能够一路追踪下去。

首先我们要定位问题出现在调用栈的哪一层，目前可以确定的是在tomcat内部出现了问题，而我们对tomcat内部的实现并不清楚，所以打算先通过stack命令看一看到底问题出在哪里

stack org.springframework.web.servlet.DispatcherServlet *

ts=2020-11-05 19:43:25;thread_name=http-nio-9220-exec-5;id=6c;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@48a5fb0a
    @org.springframework.web.servlet.DispatcherServlet.doDispatch()
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:866)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at com.netease.mail.yanxuan.eudemon.EudemonWebPageFilter.doFilter(EudemonWebPageFilter.java:111)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at com.netease.mail.dp.yxtools.starter.lamp.filter.AccessLogFilter.doFilter(AccessLogFilter.java:77)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:109)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

由于从已知的信息来看只能确认是tomcat而不是spring的问题，把排查范围缩小到了apache的包下。最初本来还怀疑过是过滤器的问题，排查后发现不是，过滤器阶段执行并没有出现超时的问题。于是把目光投向了更早的阶段，其实可以从前往后trace，如果能够复现问题，最多就只是多trace几次而已。

于是在尝试过多次之后，总算找到了相关的调用链。

trace org.apache.catalina.connector.CoyoteAdapter service '#cost > 100'

在这一层成功复现了问题

`---ts=2020-11-05 20:28:37;thread_name=http-nio-9220-exec-9;id=70;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@5eb5da12
    `---[123.176733ms] org.apache.catalina.connector.CoyoteAdapter:service()
        +---[0.001323ms] org.apache.coyote.Request:getNote() #302
        +---[9.98E-4ms] org.apache.coyote.Response:getNote() #303
        +---[0.001402ms] org.apache.catalina.connector.Connector:getXpoweredBy() #324
        +---[8.42E-4ms] org.apache.coyote.Request:getRequestProcessor() #331
        +---[9.35E-4ms] org.apache.coyote.RequestInfo:setWorkerThreadName() #331
        +---[116.02886ms] org.apache.catalina.connector.CoyoteAdapter:postParseRequest() #336
        +---[0.001032ms] org.apache.catalina.connector.Connector:getService() #339
        +---[9.81E-4ms] org.apache.catalina.Service:getContainer() #339
        +---[7.75E-4ms] org.apache.catalina.Engine:getPipeline() #339
        +---[0.001212ms] org.apache.catalina.Pipeline:isAsyncSupported() #339
        +---[8.1E-4ms] org.apache.catalina.connector.Request:setAsyncSupported() #339
        +---[4.88E-4ms] org.apache.catalina.connector.Connector:getService() #342
        +---[5.62E-4ms] org.apache.catalina.Service:getContainer() #342
        +---[5.29E-4ms] org.apache.catalina.Engine:getPipeline() #342
        +---[6.25E-4ms] org.apache.catalina.Pipeline:getFirst() #342
        +---[7.002787ms] org.apache.catalina.Valve:invoke() #342
        +---[5.69E-4ms] org.apache.catalina.connector.Request:isAsync() #345
        +---[5.26E-4ms] org.apache.catalina.connector.Request:finishRequest() #372
        +---[0.025567ms] org.apache.catalina.connector.Response:finishResponse() #373
        +---[7.24E-4ms] org.apache.coyote.Response:action() #380
        +---[5.79E-4ms] org.apache.catalina.connector.Request:isAsyncCompleting() #382
        +---[5.69E-4ms] org.apache.catalina.connector.Request:getContext() #394
        +---[5.32E-4ms] org.apache.coyote.Request:getStartTime() #401
        +---[0.001012ms] org.apache.catalina.Context:logAccess() #401
        +---[6.48E-4ms] org.apache.coyote.Request:getRequestProcessor() #406
        +---[7.68E-4ms] org.apache.coyote.RequestInfo:setWorkerThreadName() #406
        +---[0.001924ms] org.apache.catalina.connector.Request:recycle() #410
        `---[7.62E-4ms] org.apache.catalina.connector.Response:recycle() #411

可以看到，中间有一步postParseRequest耗时超过了一百毫秒，大概判定问题就出在这里，于是一路向下追踪：

`---ts=2020-11-05 20:35:07;thread_name=http-nio-9220-exec-8;id=6f;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@5eb5da12
    `---[104.480682ms] org.apache.catalina.connector.CoyoteAdapter:postParseRequest()
        ...
        +---[9.96E-4ms] org.apache.catalina.connector.Connector:getService() #679
        +---[0.001273ms] org.apache.catalina.Service:getMapper() #679
        +---[8.07E-4ms] org.apache.catalina.connector.Request:getMappingData() #679
        +---[104.258083ms] org.apache.catalina.mapper.Mapper:map() #679
        +---[0.002048ms] org.apache.catalina.connector.Request:getContext() #684
        +---[0.001473ms] 
        ...

`---ts=2020-11-05 20:42:10;thread_name=http-nio-9220-exec-11;id=bf;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@5eb5da12
    `---[102.405565ms] org.apache.catalina.mapper.Mapper:map()
        +---[5.69E-4ms] org.apache.tomcat.util.buf.MessageBytes:isNull() #693
        +---[2.21E-4ms] org.apache.tomcat.util.buf.MessageBytes:toChars() #696
        +---[2.08E-4ms] org.apache.tomcat.util.buf.MessageBytes:toChars() #697
        +---[min=1.63E-4ms,max=2.15E-4ms,total=3.78E-4ms,count=2] org.apache.tomcat.util.buf.MessageBytes:getCharChunk() #698
        `---[102.363891ms] org.apache.catalina.mapper.Mapper:internalMap() #698

`---ts=2020-11-05 20:44:31;thread_name=http-nio-9220-exec-5;id=6c;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@5eb5da12
    `---[120.95625ms] org.apache.catalina.mapper.Mapper:internalMap()
        +---[6.39E-4ms] org.apache.tomcat.util.buf.CharChunk:setLimit() #743
        +---[0.001387ms] org.apache.catalina.mapper.Mapper:exactFindIgnoreCase() #747
        ...
        `---[120.874374ms] org.apache.catalina.mapper.Mapper:internalMapWrapper() #842

接下来其实还有一大片重复的trace的过程，为了避免凑字数的嫌疑，于是把中间的过程略掉，我们直接来到终点。

trace org.apache.catalina.webresources.AbstractArchiveResourceSet getArchiveEntries '#cost > 100'

`---ts=2020-11-05 21:05:10;thread_name=http-nio-9220-exec-10;id=71;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@5eb5da12
    `---[107.813374ms] org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries()
        +---[0.060622ms] org.apache.catalina.webresources.JarWarResourceSet:openJarFile() #109
        +---[0.117106ms] org.apache.catalina.webresources.TomcatJarInputStream:<init>() #113
        +---[0.003959ms] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry() #114
        +---[min=0.004286ms,max=45.923382ms,total=107.468665ms,count=31] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry() #117
        +---[0.001131ms] org.apache.catalina.webresources.TomcatJarInputStream:getManifest() #119
        +---[0.001144ms] org.apache.catalina.webresources.JarWarResourceSet:setManifest() #120
        +---[0.001378ms] org.apache.tomcat.util.compat.JreCompat:isJre9Available() #121
        +---[0.001158ms] org.apache.catalina.webresources.TomcatJarInputStream:getMetaInfEntry() #133
        +---[7.3E-4ms] org.apache.catalina.webresources.TomcatJarInputStream:getManifestEntry() #137
        +---[0.003802ms] org.apache.catalina.webresources.TomcatJarInputStream:close() #141
        `---[0.00137ms] org.apache.catalina.webresources.JarWarResourceSet:closeJarFile() #151

到这里发现trace进行不下去了，因为这个方法实际上已经到达了jdk层。这时就可以停下来去看看源码，或者通过执行watch指令来观察一下getNextJarEntry这个方法。

为了能够对jdk方法进行trace，还需要修改unsafe为true

[arthas@10635]$ options unsafe true
 NAME    BEFORE-VALUE  AFTER-VALUE
-----------------------------------
 unsafe  false         true

找到这个方法的实现，并对其使用watch命令

watch java.util.jar.JarInputStream getNextJarEntry "{returnObj}"

截取的一部分返回结果，发现里面都是对swagger相关静态资源的读取

...
ts=2020-11-12 19:57:45; [cost=0.036438ms] result=@ArrayList[
    @JarEntry[META-INF/resources/webjars/springfox-swagger-ui/],
]
ts=2020-11-12 19:57:45; [cost=0.033087ms] result=@ArrayList[
    @JarEntry[META-INF/resources/webjars/springfox-swagger-ui/favicon-16x16.png],
]
ts=2020-11-12 19:57:45; [cost=0.038763ms] result=@ArrayList[
    @JarEntry[META-INF/resources/webjars/springfox-swagger-ui/springfox.css],
]
ts=2020-11-12 19:57:45; [cost=0.105798ms] result=@ArrayList[
    @JarEntry[META-INF/resources/webjars/springfox-swagger-ui/swagger-ui-standalone-preset.js.map],
]
ts=2020-11-12 19:57:45; [cost=25.00276ms] result=@ArrayList[
    @JarEntry[META-INF/resources/webjars/springfox-swagger-ui/swagger-ui.css],
]
...

感觉找到了问题的关键，应该是由于需要加载静态资源才导致响应时间变长，但是并不是每个请求都会出现这种问题，怀疑是有缓存存在的原因。

最后，将swagger相关依赖都排除掉，再次测试，问题并没有再出现，验证了上面的结论，也解决了这个问题。

事后思考

到这里虽然看似解决了问题，皆大欢喜，但是却没有去探究更深层次的原因。还有很多疑惑没有得到解答。

• 为什么请求会一直要加载静态资源？
• 如果一定需要使用swagger是不是就无解？

以我自己当前的水平，寻找这些问题的答案可能会比较费劲，于是我想了个轻松一点的办法，上网找答案。最初因为没有定位到具体的原因，在网上找解决方法就会跟大海捞针一样，但是定位到某个依赖之后，通过关键词能够很快地找到相关问题。

对于第一个问题，每次请求都尝试加载静态资源这是tomcat在当前版本下的bug，tomcat在高版本中修复了这个bug。在代码里增加了一层判断，来控制在非必要情况下对getResource方法的调用，在

When considering rule 7, Mapper.internalMapWrapper makes a call to WebResourceRoot.getResource(String) that is only necessary if Context.getMapperDirectoryRedirectEnabled() returns true. It looks like the logic could be reworked so that enablement of the redirect is checked first, and the getResource(String) call is then only made when it is enabled.

This was originally discussed with Mark Thomas in the context of a Spring Boot issue. Please see https://github.com/spring-projects/spring-boot/issues/8522#issuecomment-443177285 for further details.

第二个问题也得到了解决，既然tomcat已经在更高的版本中修复了这个bug，那么只需要升级到合适的版本也就没有问题了。

Fixed in:
- trunk for 9.0.14 onwards
- 8.5.x for 8.5.36 onwards

(7.0.x has a different resources implementation)

所以，在需要使用swagger的应用下，也可以通过将tomcat的版本升级至8.5.37及以上的版本来解决。

参考资料

https://www.twblogs.net/a/5d7d1efbbd9eee541c3443da

https://bz.apache.org/bugzilla/show_bug.cgi?id=62968

https://github.com/spring-projects/spring-boot/issues/8522