使用 Arthas 排查 SpringBoot 诡异耗时的 Bug

转载

mb5fe55a1c73221 2021-03-16 11:02:00

文章标签 java apache spring tomcat .net 文章分类 代码人生

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

使用 Arthas 排查 SpringBoot 诡异耗时的 Bug_tomcat

背景

公司有个渠道系统，专门对接三方渠道使用，没有什么业务逻辑，主要是转换报文和参数校验之类的工作，起着一个承上启下的作用。

最近在优化接口的响应时间，优化了代码之后，但是时间还是达不到要求；有一个诡异的 100ms 左右的耗时问题，在接口中打印了请求处理时间后，和调用方的响应时间还有差了 100ms 左右。比如程序里记录 150ms，但是调用方等待时间却为 250ms 左右。

下面记录下当时详细的定位 & 解决流程（其实解决很简单，关键在于怎么定位并找到解决问题的方法）。

定位过程1. 分析代码

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

2. 分析调用流程

出现这个问题之后，首先确认了下接口的调用流程。由于是内部测试，所以调用流程较少。

Nginx -反向代理-> 渠道系统

公司是云服务器，网络走的也是云的内网。由于不明确问题的原因，所以用排除法，首先确认服务器网络是否有问题。

先确认发送端到 Nginx Host 是否有问题：

[jboss@VM_0_139_centos ~]$ ping 10.0.0.139 PING 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 ms 64 bytes from 10.0.0.139: icmp_seq=2 ttl=64 time=0.041 ms 64 bytes from 10.0.0.139: icmp_seq=3 ttl=64 time=0.040 ms 64 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.139 PING 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 ms 64 bytes from 10.0.0.139: icmp_seq=2 ttl=64 time=0.041 ms 64 bytes from 10.0.0.139: icmp_seq=3 ttl=64 time=0.040 ms 64 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/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 的介绍可以参考我的另一篇文章）。就算不开启 keep-alive，每次重新 handshake，也不至于需要 70ms。

经过不断分析测试发现，连续请求的话时间就会很短，每次请求只需要几毫秒，但是如果隔一段时间再请求，就会花费 70ms 以上。

从这个现象猜想，可能是某些缓存机制导致的，连续请求因为有缓存，所以速度快，时间长缓存失效后导致时间长。

那么这个问题点到底在哪一层呢？tomcat 层还是 spring-webmvc 呢？

光猜想定位不了问题，还是得实际测试一下，把渠道系统的代码放到本地 IDE 里启动测试能否复现。

但是导入本地 IDE 后，在 IDE 中启动后并不能复现问题，并没有 70+ms 的延迟问题。这下头疼了，本地无法复现，不能 Debug，由于问题点不在业务代码，也不能通过加日志的方式来 Debug。

这时候可以祭出神器 Arthas 了。

3. Arthas 分析问题

Arthas 是 Alibaba 开源的 Java 诊断工具，深受开发者喜爱。当你遇到以下类似问题而束手无策时，Arthas 可以帮助你解决：

这个类从哪个 jar 包加载的？为什么会报各种类相关的 Exception？
我改的代码为什么没有执行到？难道是我没 commit？分支搞错了？
遇到问题无法在线上 debug，难道只能通过加日志再重新发布吗？
线上遇到某个用户的数据处理有问题，但线上同样无法 debug，线下无法重现！
是否有一个全局视角来查看系统的运行状况？
有什么办法可以监控到 JVM 的实时运行状态？
······

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

trace 方法内部调用路径，并输出方法路径上的每个节点上耗时。
trace 命令能主动搜索 class-pattern／method-pattern 。
对应的方法调用路径，渲染和统计整个调用链路上的所有性能开销和追踪调用链路。

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

[arthas@24851]$ trace org.springframework.web.servlet.DispatcherServlet * Press Q or Ctrl+C to abort. Affect(class-cnt:1 , method-cnt:44) cost in 508 ms. `---ts=2019-09-14 21:07:44;thread_name=http-nio-7744-exec-2;id=11;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7c136917     `---[2.952142ms] org.springframework.web.servlet.DispatcherServlet:buildLocaleContext() `---ts=2019-09-14 21:07:44;thread_name=http-nio-7744-exec-2;id=11;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7c136917     `---[18.08903ms] org.springframework.web.servlet.DispatcherServlet:doService()         +---[0.041346ms] org.apache.commons.logging.Log:isDebugEnabled() #889         +---[0.022398ms] org.springframework.web.util.WebUtils:isIncludeRequest() #898         +---[0.014904ms] org.springframework.web.servlet.DispatcherServlet:getWebApplicationContext() #910         +---[1.071879ms] javax.servlet.http.HttpServletRequest:setAttribute() #910         +---[0.020977ms] javax.servlet.http.HttpServletRequest:setAttribute() #911         +---[0.017073ms] javax.servlet.http.HttpServletRequest:setAttribute() #912         +---[0.218277ms] org.springframework.web.servlet.DispatcherServlet:getThemeSource() #913         |   `---[0.137568ms] org.springframework.web.servlet.DispatcherServlet:getThemeSource()         |       `---[min=0.00783ms,max=0.014251ms,total=0.022081ms,count=2] org.springframework.web.servlet.DispatcherServlet:getWebApplicationContext() #782         +---[0.019363ms] javax.servlet.http.HttpServletRequest:setAttribute() #913         +---[0.070694ms] org.springframework.web.servlet.FlashMapManager:retrieveAndUpdate() #916         +---[0.01839ms] org.springframework.web.servlet.FlashMap:<init>() #920         +---[0.016943ms] javax.servlet.http.HttpServletRequest:setAttribute() #920         +---[0.015268ms] javax.servlet.http.HttpServletRequest:setAttribute() #921         +---[15.050124ms] org.springframework.web.servlet.DispatcherServlet:doDispatch() #925         |   `---[14.943477ms] org.springframework.web.servlet.DispatcherServlet:doDispatch()         |       +---[0.019135ms] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #953         |       +---[2.108373ms] org.springframework.web.servlet.DispatcherServlet:checkMultipart() #960         |       |   `---[2.004436ms] org.springframework.web.servlet.DispatcherServlet:checkMultipart()         |       |       `---[1.890845ms] org.springframework.web.multipart.MultipartResolver:isMultipart() #1117         |       +---[2.054361ms] org.springframework.web.servlet.DispatcherServlet:getHandler() #964         |       |   `---[1.961963ms] org.springframework.web.servlet.DispatcherServlet:getHandler()         |       |       +---[0.02051ms] java.util.List:iterator() #1183         |       |       +---[min=0.003805ms,max=0.009641ms,total=0.013446ms,count=2] java.util.Iterator:hasNext() #1183         |       |       +---[min=0.003181ms,max=0.009751ms,total=0.012932ms,count=2] java.util.Iterator:next() #1183         |       |       +---[min=0.005841ms,max=0.015308ms,total=0.021149ms,count=2] org.apache.commons.logging.Log:isTraceEnabled() #1184         |       |       `---[min=0.474739ms,max=1.19145ms,total=1.666189ms,count=2] org.springframework.web.servlet.HandlerMapping:getHandler() #1188         |       +---[0.013071ms] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #971         |       +---[0.372236ms] org.springframework.web.servlet.DispatcherServlet:getHandlerAdapter() #971         |       |   `---[0.280073ms] org.springframework.web.servlet.DispatcherServlet:getHandlerAdapter()         |       |       +---[0.004804ms] java.util.List:iterator() #1224         |       |       +---[0.003668ms] java.util.Iterator:hasNext() #1224         |       |       +---[0.003038ms] java.util.Iterator:next() #1224         |       |       +---[0.006451ms] org.apache.commons.logging.Log:isTraceEnabled() #1225         |       |       `---[0.012683ms] org.springframework.web.servlet.HandlerAdapter:supports() #1228         |       +---[0.012848ms] javax.servlet.http.HttpServletRequest:getMethod() #974         |       +---[0.013132ms] java.lang.String:equals() #975         |       +---[0.003025ms] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #977         |       +---[0.008095ms] org.springframework.web.servlet.HandlerAdapter:getLastModified() #977         |       +---[0.006596ms] org.apache.commons.logging.Log:isDebugEnabled() #978         |       +---[0.018024ms] org.springframework.web.context.request.ServletWebRequest:<init>() #981         |       +---[0.017869ms] org.springframework.web.context.request.ServletWebRequest:checkNotModified() #981         |       +---[0.038542ms] org.springframework.web.servlet.HandlerExecutionChain:applyPreHandle() #986         |       +---[0.00431ms] org.springframework.web.servlet.HandlerExecutionChain:getHandler() #991         |       +---[4.248493ms] org.springframework.web.servlet.HandlerAdapter:handle() #991         |       +---[0.014805ms] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #993         |       +---[1.444994ms] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName() #997         |       |   `---[0.067631ms] org.springframework.web.servlet.DispatcherServlet:applyDefaultViewName()         |       +---[0.012027ms] org.springframework.web.servlet.HandlerExecutionChain:applyPostHandle() #998         |       +---[0.373997ms] org.springframework.web.servlet.DispatcherServlet:processDispatchResult() #1008         |       |   `---[0.197004ms] org.springframework.web.servlet.DispatcherServlet:processDispatchResult()         |       |       +---[0.007074ms] org.apache.commons.logging.Log:isDebugEnabled() #1075         |       |       +---[0.005467ms] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #1081         |       |       +---[0.004054ms] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1081         |       |       `---[0.011988ms] org.springframework.web.servlet.HandlerExecutionChain:triggerAfterCompletion() #1087         |       `---[0.004015ms] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #1018         +---[0.005055ms] org.springframework.web.context.request.async.WebAsyncUtils:getAsyncManager() #928         `---[0.003422ms] org.springframework.web.context.request.async.WebAsyncManager:isConcurrentHandlingStarted() #928

[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

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

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

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

不过没关系，有神器 Arthas，可以通过 stack 命令来反向查找调用路径，以

org.springframework.web.servlet.DispatcherServlet 作为参数：

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

[arthas@24851]$ stack org.springframework.web.servlet.DispatcherServlet * Press Q or Ctrl+C to abort. Affect(class-cnt:1 , method-cnt:44) cost in 495 ms. ts=2019-09-14 21:15:19;thread_name=http-nio-7744-exec-5;id=14;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7c136917     @org.springframework.web.servlet.FrameworkServlet.processRequest()         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 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:81)         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:1149)         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)         at java.lang.Thread.run(Thread.java:748) ts=2019-09-14 21:15:19;thread_name=http-nio-7744-exec-5;id=14;is_daemon=true;priority=5;TCCL=org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader@7c136917     @org.springframework.web.servlet.DispatcherServlet.doService()         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 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:81)         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:1149)         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)         at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)         at java.lang.Thread.run(Thread.java:748)

从 stack 日志上可以很直观的看出 DispatchServlet 的调用栈，那么这么长的路径，该 trace 哪个类呢（这里跳过 spring mvc 中的过滤器的 trace 过程，实际排查的时候也 trace 了一遍，但这诡异的时间消耗不是由这里过滤器产生的）？有一定经验的老司机从名字上大概也能猜出来从哪里下手比较好，那就是

org.apache.coyote.http11.Http11Processor.service，从名字上看，http1.1 处理器，这可能是一个比较好的切入点。下面来 trace 一下：

[arthas@24851]$ trace org.apache.coyote.http11.Http11Processor service Press Q or Ctrl+C to abort. Affect(class-cnt:1 , method-cnt:1) cost in 269 ms. `---ts=2019-09-14 21:22:51;thread_name=http-nio-7744-exec-8;id=17;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@20ad9418     `---[131.650285ms] org.apache.coyote.http11.Http11Processor:service()         +---[0.036851ms] org.apache.coyote.Request:getRequestProcessor() #667         +---[0.009986ms] org.apache.coyote.RequestInfo:setStage() #668         +---[0.008928ms] org.apache.coyote.http11.Http11Processor:setSocketWrapper() #671         +---[0.013236ms] org.apache.coyote.http11.Http11InputBuffer:init() #672         +---[0.00981ms] org.apache.coyote.http11.Http11OutputBuffer:init() #673         +---[min=0.00213ms,max=0.007317ms,total=0.009447ms,count=2] org.apache.coyote.http11.Http11Processor:getErrorState() #683         +---[min=0.002098ms,max=0.008888ms,total=0.010986ms,count=2] org.apache.coyote.ErrorState:isError() #683         +---[min=0.002448ms,max=0.007149ms,total=0.009597ms,count=2] org.apache.coyote.http11.Http11Processor:isAsync() #683         +---[min=0.002399ms,max=0.00852ms,total=0.010919ms,count=2] org.apache.tomcat.util.net.AbstractEndpoint:isPaused() #683         +---[min=0.033587ms,max=0.11832ms,total=0.151907ms,count=2] org.apache.coyote.http11.Http11InputBuffer:parseRequestLine() #687         +---[0.005384ms] org.apache.tomcat.util.net.AbstractEndpoint:isPaused() #695         +---[0.007924ms] org.apache.coyote.Request:getMimeHeaders() #702         +---[0.006744ms] org.apache.tomcat.util.net.AbstractEndpoint:getMaxHeaderCount() #702         +---[0.012574ms] org.apache.tomcat.util.http.MimeHeaders:setLimit() #702         +---[0.14319ms] org.apache.coyote.http11.Http11InputBuffer:parseHeaders() #703         +---[0.003997ms] org.apache.coyote.Request:getMimeHeaders() #743         +---[0.026561ms] org.apache.tomcat.util.http.MimeHeaders:values() #743         +---[min=0.002869ms,max=0.01203ms,total=0.014899ms,count=2] java.util.Enumeration:hasMoreElements() #745         +---[0.070114ms] java.util.Enumeration:nextElement() #746         +---[0.010921ms] java.lang.String:toLowerCase() #746         +---[0.008453ms] java.lang.String:contains() #746         +---[0.002698ms] org.apache.coyote.http11.Http11Processor:getErrorState() #775         +---[0.00307ms] org.apache.coyote.ErrorState:isError() #775         +---[0.002708ms] org.apache.coyote.RequestInfo:setStage() #777         +---[0.171139ms] org.apache.coyote.http11.Http11Processor:prepareRequest() #779         +---[0.009349ms] org.apache.tomcat.util.net.SocketWrapperBase:decrementKeepAlive() #794         +---[0.002574ms] org.apache.coyote.http11.Http11Processor:getErrorState() #800         +---[0.002696ms] org.apache.coyote.ErrorState:isError() #800         +---[0.002499ms] org.apache.coyote.RequestInfo:setStage() #802         +---[0.005641ms] org.apache.coyote.http11.Http11Processor:getAdapter() #803         +---[129.868916ms] org.apache.coyote.Adapter:service() #803         +---[0.003859ms] org.apache.coyote.http11.Http11Processor:getErrorState() #809         +---[0.002365ms] org.apache.coyote.ErrorState:isError() #809         +---[0.003844ms] org.apache.coyote.http11.Http11Processor:isAsync() #809         +---[0.002382ms] org.apache.coyote.Response:getStatus() #809         +---[0.002476ms] org.apache.coyote.http11.Http11Processor:statusDropsConnection() #809         +---[0.002284ms] org.apache.coyote.RequestInfo:setStage() #838         +---[0.00222ms] org.apache.coyote.http11.Http11Processor:isAsync() #839         +---[0.037873ms] org.apache.coyote.http11.Http11Processor:endRequest() #843         +---[0.002188ms] org.apache.coyote.RequestInfo:setStage() #845         +---[0.002112ms] org.apache.coyote.http11.Http11Processor:getErrorState() #849         +---[0.002063ms] org.apache.coyote.ErrorState:isError() #849         +---[0.002504ms] org.apache.coyote.http11.Http11Processor:isAsync() #853         +---[0.009808ms] org.apache.coyote.Request:updateCounters() #854         +---[0.002008ms] org.apache.coyote.http11.Http11Processor:getErrorState() #855         +---[0.002192ms] org.apache.coyote.ErrorState:isIoAllowed() #855         +---[0.01968ms] org.apache.coyote.http11.Http11InputBuffer:nextRequest() #856         +---[0.010065ms] org.apache.coyote.http11.Http11OutputBuffer:nextRequest() #857         +---[0.002576ms] org.apache.coyote.RequestInfo:setStage() #870         +---[0.016599ms] org.apache.coyote.http11.Http11Processor:processSendfile() #872         +---[0.008182ms] org.apache.coyote.http11.Http11InputBuffer:getParsingRequestLinePhase()

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。