用 Arthas 定位 Spring Boot 接口的超时问题,让应用起飞( 五 )

日志里有一个129ms的耗时点(时间比没开arthas的时候更长是因为arthas本身带来的性能消耗,所以生产环境小心使用),这个就是要找的问题点 。
打问题点找到了,那怎么定位是什么导致的问题呢,又如何解决呢?
继续trace吧,细化到具体的代码块或者内容 。trace由于性能考虑,不会展示所有的调用路径,如果调用路径过深,只有手动深入trace , 原则就是trace耗时长的那个方法:
[arthas@24851]$ trace org.apache.coyote.Adapter servicePress Q or Ctrl+C to abort.Affect(class-cnt:1 , method-cnt:1) cost in 608 ms.`---ts=2019-09-14 21:34:33;thread_name=http-nio-7744-exec-1;id=10;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@20ad9418`---[81.70999ms] org.apache.catalina.connector.CoyoteAdapter:service()+---[0.032546ms] org.apache.coyote.Request:getNote() #302+---[0.007148ms] org.apache.coyote.Response:getNote() #303+---[0.007475ms] org.apache.catalina.connector.Connector:getXpoweredBy() #324+---[0.00447ms] org.apache.coyote.Request:getRequestProcessor() #331+---[0.007902ms] java.lang.ThreadLocal:get() #331+---[0.006522ms] org.apache.coyote.RequestInfo:setWorkerThreadName() #331+---[73.793798ms] org.apache.catalina.connector.CoyoteAdapter:postParseRequest() #336+---[0.001536ms] org.apache.catalina.connector.Connector:getService() #339+---[0.004469ms] org.apache.catalina.Service:getContainer() #339+---[0.007074ms] org.apache.catalina.Engine:getPipeline() #339+---[0.004334ms] org.apache.catalina.Pipeline:isAsyncSupported() #339+---[0.002466ms] org.apache.catalina.connector.Request:setAsyncSupported() #339+---[6.01E-4ms] org.apache.catalina.connector.Connector:getService() #342+---[0.001859ms] org.apache.catalina.Service:getContainer() #342+---[9.65E-4ms] org.apache.catalina.Engine:getPipeline() #342+---[0.005231ms] org.apache.catalina.Pipeline:getFirst() #342+---[7.239154ms] org.apache.catalina.Valve:invoke() #342+---[0.006904ms] org.apache.catalina.connector.Request:isAsync() #345+---[0.00509ms] org.apache.catalina.connector.Request:finishRequest() #372+---[0.051461ms] org.apache.catalina.connector.Response:finishResponse() #373+---[0.007244ms] java.util.concurrent.atomic.AtomicBoolean:<init>() #379+---[0.007314ms] org.apache.coyote.Response:action() #380+---[0.004518ms] org.apache.catalina.connector.Request:isAsyncCompleting() #382+---[0.001072ms] org.apache.catalina.connector.Request:getContext() #394+---[0.007166ms] java.lang.System:currentTimeMillis() #401+---[0.004367ms] org.apache.coyote.Request:getStartTime() #401+---[0.011483ms] org.apache.catalina.Context:logAccess() #401+---[0.0014ms] org.apache.coyote.Request:getRequestProcessor() #406+---[min=8.0E-4ms,max=9.22E-4ms,total=0.001722ms,count=2] java.lang.Integer:<init>() #406+---[0.001082ms] java.lang.reflect.Method:invoke() #406+---[0.001851ms] org.apache.coyote.RequestInfo:setWorkerThreadName() #406+---[0.035805ms] org.apache.catalina.connector.Request:recycle() #410`---[0.007849ms] org.apache.catalina.connector.Response:recycle() #411一段无聊的手动深入trace之后………………
[arthas@24851]$ trace org.apache.catalina.webresources.AbstractArchiveResourceSet getArchiveEntriesPress Q or Ctrl+C to abort.Affect(class-cnt:4 , method-cnt:2) cost in 150 ms.`---ts=2019-09-14 21:36:26;thread_name=http-nio-7744-exec-3;id=12;is_daemon=true;priority=5;TCCL=org.springframework.boot.loader.LaunchedURLClassLoader@20ad9418`---[75.743681ms] org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries()+---[0.025731ms] java.util.HashMap:<init>() #106+---[0.097729ms] org.apache.catalina.webresources.JarWarResourceSet:openJarFile() #109+---[0.091037ms] java.util.jar.JarFile:getJarEntry() #110+---[0.096325ms] java.util.jar.JarFile:getInputStream() #111+---[0.451916ms] org.apache.catalina.webresources.TomcatJarInputStream:<init>() #113+---[min=0.001175ms,max=0.001176ms,total=0.002351ms,count=2] java.lang.Integer:<init>() #114+---[0.00104ms] java.lang.reflect.Method:invoke() #114+---[0.045105ms] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry() #114+---[min=5.02E-4ms,max=0.008531ms,total=0.028864ms,count=31] java.util.jar.JarEntry:getName() #116+---[min=5.39E-4ms,max=0.022805ms,total=0.054647ms,count=31] java.util.HashMap:put() #116+---[min=0.004452ms,max=34.479307ms,total=74.206249ms,count=31] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry() #117+---[0.018358ms] org.apache.catalina.webresources.TomcatJarInputStream:getManifest() #119+---[0.006429ms] org.apache.catalina.webresources.JarWarResourceSet:setManifest() #120+---[0.010904ms] org.apache.tomcat.util.compat.JreCompat:isJre9Available() #121+---[0.003307ms] org.apache.catalina.webresources.TomcatJarInputStream:getMetaInfEntry() #133+---[5.5E-4ms] java.util.jar.JarEntry:getName() #135+---[6.42E-4ms] java.util.HashMap:put() #135+---[0.001981ms] org.apache.catalina.webresources.TomcatJarInputStream:getManifestEntry() #137+---[0.064484ms] org.apache.catalina.webresources.TomcatJarInputStream:close() #141+---[0.007961ms] org.apache.catalina.webresources.JarWarResourceSet:closeJarFile() #151`---[0.004643ms] java.io.InputStream:close() #155


推荐阅读