背??景公司有渠道系统，专门用来对接第三方渠道。没有业务逻辑。主要是报文的转换和参数的校验，起到承上启下的作用。最近优化了接口的响应时间，优化了代码，时间还是达不到要求；有一个100ms左右的奇怪耗时问题。在接口中打印请求处理时间后，与调用方的响应时间还是有差距的。差异约为100ms。比如程序记录了150ms，但是调用者等待了大约250ms。下面记录下当时详细的定位&解决过程（其实解决起来很简单，关键在于如何定位问题，找到解决问题的方法）。一、定位流程分析码道系统是一个常见的使用集成tomcat的spring-bootweb项目。分析代码发现没有特别的地方，没有特别的过滤器或者拦截器，所以初步判断是业务代码问题。分析调用流程出现这个问题，首先确认下一个接口的调用流程。由于是内测，所以来电较少。Nginx-反向代理->通道系统公司是云服务器，网络也是云的内网。由于问题的原因还不清楚，所以先用排除的方法确认一下是不是服务器网络有问题。首先确认发往NginxHost的发件人是否有问题：[jboss@VM_0_139_centos~]$ping10.0.0.139PING10.0.0.139(10.0.0.139)56(84)bytesofdata.64bytesfrom10.0.0.139:icmp_seq=1ttl=64时间=0.029ms64字节来自10.0.0.139：icmp_seq=2ttl=64时间=0.041ms64字节来自10.0.0.139：icmp_seq=3ttl=64时间=0.040ms64字节来自10.0.0.139：icmp_seq4ttl=time=0.040ms从ping结果来看，从发送端到Nginx主机的延迟是没有问题的。接下来查看Nginx到channel系统的网络。#既然日志没问题，这里直接复制上面的日志[jboss@VM_0_139_centos~]$ping10.0.0.139PING10.0.0.139(10.0.0.139)56(84)bytesofdata.64bytesfrom10.0.0.139:icmp_seq=1ttl=64时间=0.029ms64字节来自10.0.0.139：icmp_seq=2ttl=64时间=0.041ms64字节来自10.0.0.139：icmp_seq=3ttl=64时间=0.040ms64字节来自10.0.0.139：4icmp_seq=ttl=64time=0.040ms从ping结果来看，Nginx到通道系统服务器的网络延迟没有问题。既然网络好像没问题，可以继续淘汰Nginx，客户端直接在通道系统的服务器上。,直接通过loopback地址(localhost)连接，避免走网卡/dns，缩小问题范围看能否重现（这个应用和地址是我后面模拟的，测试是空接口）：[jboss@VM_10_91_centostmp]$curl-w"@curl-time.txt"http://127.0.0.1:7744/sendsuccesshttp:200dns:0.001sredirect:0.000stime_connect:0.001stime_appconnect:0.000stime_pretransfer:0.001stime_starttransfer:0.073ssize_download:7bytesspeed_download:95.000B/s--------time_total:0.073s请求总耗时从curl日志看，调用一次耗时73ms通过环回地址的空接口。这就奇怪了，跳过中间所有的调用节点（包括filters&interceptors等），直接请求申请一个空接口，用了73ms再看看：[jboss@VM_10_91_centostmp]$curl-w"@curl-time.txt"http://127.0.0.1:7744/sendsuccesshttp:200dns:0.001sredirect:0.000stime_connect:0.001stime_appconnect:0.000stime_pretransfer:0.001stime_starttransfer:0.003s:size_download7bytesspeed_download:2611.000B/s--------time_total:0.003s更奇怪的是第二次请求的耗时是正常的，变成了3ms。查阅了资料，linuxcurl默认开启了httpkeep-alive。即使不开启keep-alive，每次重新握手也不用70ms。经过不断的分析和测试，发现连续请求的时间会很短，每次请求只需要几毫秒，但如果过段时间再请求，则需要70ms以上。从这个现象，猜测可能是某种缓存机制导致的。连续请求快是因为有缓存，时间长了会导致缓存失效后时间长。那么问题出在哪里呢？Tomcat层还是spring-webmvc？光靠猜测是定位不了问题的，还是要实际测试一下，把通道系统的代码放到本地ide里开始测试，看看能不能重现。但是导入本地ide后，在ide中启动后问题无法复现，也没有70+ms的延迟问题。这个很头疼，本地无法复现，无法调试。由于问题不在业务代码中，所以无法通过添加日志的方式进行调试。这个时候，神器阿尔萨斯就可以献祭了。2、Arthas分析问题Arthas是阿里巴巴开源的Java诊断工具，深受开发者喜爱。当你遇到以下类似问题而束手无策时，Arthas可以帮你解决：1、这个类是从哪个jar包加载的？为什么会报各种类型的相关Exception？2、为什么我改的代码没有执行？难道是我没犯？分支错了？3、遇到问题不能在线调试，只能加日志重新发布吗？4、某用户线上数据处理有问题，但线上无法调试，线下无法重现！5.是否有全局视角来查看系统的健康状况？6、有什么方法可以监控JVM的实时运行状态？以上就是对Arthas的官方介绍，这次我只需要用到他的一个小功能trace即可。动态计算方法调用路径和时间，这样我就可以定位到哪里消耗了时间。1.trace方法内部调用路径，输出方法路径上每个节点花费的时间。2、trace命令可以主动搜索class-pattern/method-pattern。3.对应的方法调用路径，整个调用链路和跟踪调用链路的所有性能开销的渲染和统计。有了神器，追踪的方法是什么？由于本人对Tomcat的源码不是很熟悉，只能从springmvc入手。先追查springmvc的入口：[jboss@VM_10_91_centostmp]$curl-w"@curl-time.txt"http://127.0.0.1:7744/sendsuccesshttp:200dns:0.001sredirect:0.000stime_connect:0.001stime_appconnect:0.000stime_pretransfer:0.001stime_starttransfer:0.115ssize_download:7bytesspeed_download:60.0------0Btime_total:0.115s这个调用在调用端耗时115ms，但是从arthastrace来看，springmvc只消耗了18ms，那么剩下的97ms去哪了呢？经过本地测试，可以排除springmvc的问题。最后也是唯一可能的问题是tomcat，但是我对tomcat里面的源码不熟悉，连request入口都不清楚，tomcat里面需要trace的类也不好找。...不过没关系，Arthas有个神器，可以通过stack命令反转调用路径，把org.springframework.web.servlet.DispatcherServlet作为参数："stack输出当前方法的调用路径很多时候我们知道执行了一个方法，但是这个方法执行的路径有很多，或者你根本不知道这个方法是从哪里执行的，这时候你需要的就是stack命令。》从stacklog可以很直观的看到DispatchServlet的调用栈，那么这么长的路径到底应该trace到哪个类（这里略过springmvc中filter的trace过程，在实际调查。但是这个怪异的耗时不是这里的过滤器造成的）？有经验的驱动大概能从名字猜到从哪里开始，也就是org.apache.coyote.http11.Http11Processor.service，从名字看，http1.1处理器，这可能是一个比较好的切入点，我们来追踪一下：日志中有一个129ms的耗时点（这个时间比没有开启arthas时长，因为arthas本身带来了性能消耗，所以用它仔细在生产环境），这就是要找的问题，如果发现问题，如何定位问题，如何解决？继续追溯细化到具体的代码块或内容。出于性能考虑，trace不会显示所有的调用路径。如果调用路径太深，只能手动深入trace。原理就是trace时间长的方法：无聊的手动deeptrace之后...找到一个值得思考的Pause：+---[min=0.004452ms,max=34.479307ms,total=74.206249ms,count=31]org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry()#117这行代码加载了31次，总共耗时74ms；从名字上看应该是tomcat加载jar包的时候很耗时，那么到底是加载31个jar包耗时呢，还是31次加载jar包中的某些资源耗时呢？？TomcatJarInputStream此类源评论写道：此子类的目的是获取对META-INF/和META-INF/MANIFEST.MF的JarEntry对象的引用，否则这些引用将被JarInputStream实现吞噬。大概意思就是，获取jar包中META-INF/、META-INF/MANIFEST的资源。这是一个子类，更多的功能在父类JarInputStream中。其实看到这里你大概就能猜到问题所在了。Tomcat加载jar包中META-INF/和META-INF/MANIFEST的资源。下面介绍源码分析）不要着急定位问题，尝试通过Arthas最终定位到问题的细节，继续手动下钻trace。[arthas@24851]$traceorg.apache.catalina.webresources.TomcatJarInputStream*PressQorCtrl+Ctoabort.Affect(class-cnt:1,method-cnt:4)costin44ms.`---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类的源码：/***CreatesanewJarEntry(ZipEntry)for*指定的JAR文件条目名称。*指定JAR文件条目名称的清单属性将被复制到新的*JarEntry。**@paramnameJAR/ZIP文件条目的名称*@returnJarEntry刚刚创建的对象*/protectedZipEntrycreateZipEntry(Stringname){JarEntrye=newJarEntry(name);if(man!=null){e.attr=man.getAttributes(name);}返回e;}这个createZipEntry有一个名称参数。根据注释，它是jar/zip文件的名称。如果能拿到文件名的关键信息，就可以直接定位问题；或者通过Arthas，使用watch命令动态监控方法调用数据。watch方法执行数据观察“让你轻松观察指定方法的调用，可以观察的范围是：返回值、抛出异常、输入参数、通过编写OGNL表达式查看对应的变量”。watch方法的输入参数。现在可以直接看到具体加载资源的名字了，这么熟悉的名字：swagger-ui，国外的一个rest接口文档工具，国内开发者基于swagger-ui做了一套springmvc集成工具，通过注解的方式可以自动生成swagger-ui需要的接口定义json文件，使用起来比较方便，但是侵入性比较大。删除swaggerjar包后，怪异的70+ms就消失了。
