SpringBoot接口频繁超时,长时间找不到原因,我用 Arthas 定位到了( 二 )


经过不断分析测试发现,连续请求的话时间就会很短,每次请求只需要几毫秒,但是如果隔一段时间再请求,就会花费70ms以上 。
从这个现象猜想,可能是某些缓存机制导致的,连续请求因为有缓存,所以速度快,时间长缓存失效后导致时间长 。
那么这个问题点到底在哪一层呢?tomcat层还是spring-webmvc呢?
光猜想定位不了问题,还是得实际测试一下,把渠道系统的代码放到本地ide里启动测试能否复现

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

文章插图
但是导入本地Ide后,在Ide中启动后并不能复现问题,并没有70+ms的延迟问题 。这下头疼了,本地无法复现,不能Debug,由于问题点不在业务代码,也不能通过加日志的方式来Debug
这时候可以祭出神器Arthas了
 
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


推荐阅读