记一次接口超时问题排查

今天生产环境突然出现一个老接口的p95响应耗时超1秒的告警。由于没有任何变更，有点奇怪，于是开始了探索之旅……
首先常规排错思路，看直接告警信息。告警是ng上的接口响应耗时，由于ng一般只做转发或者负载均衡，没有什么逻辑，除非资源瓶颈和很高并发一般不会有什么压力。而ng的资源消耗都很低，基本排除ng的性能瓶颈导致。接着看nginx.conf 的配置，upstream是一组jetty服务。结合ng上的日志登录jetty服务器查看日志。由于没有记录有效的request 请求日志。至此通过日志链路报错线索中断了……
由于我的系统没有任何变更和版本下发，另外排除了没有监控误告，初步猜测是下游接口响应耗时增加了。但下游系统运维响应不给力，死活不承认他们接口耗时增加。作为一个技术人，用技术的手段证实（证否）自己的怀疑，是基本的素养。于是收集证据，打脸下游系统运维的旅程开始了。
在ng上实时监控耗时超1秒的接口，使用tail -100f access.log | grep -i "interface key word"| awk '{if($35 > 1) print}',同时在所有jetty服务器上使用tcpdump tcp -i eth0 -w /tmp/$(hostname -i)_$(date + %T).pcap -s 0 -vvv,一直跑着直到再次出现ng超时1秒的接口日志。
接着使用whireshark软件分析下载抓到的*.pcap文件。
whireshark是个宝藏软件，可以深度挖掘一下，改天再写个文章。
我一般使用whireshark的思路是，先使用已知的信息，比如:源ip，目标ip，接口关键字、请求时间等去定位数据包。由于此次很明确调用链路，于是先使用过滤器ip.addr == 10.117.51.*** and http.request_uri contains "interface key word"，过滤出来一部分数据包。再调整whireshark的“视图”调整时间为”年月日时分秒格式”，再定位tcp index,比如7599。最后再会用过滤器tcp.stream == 7599查看tcp 流。通过三次握手确定tcp连接起始点，再选中数据包，右键复制为“……as printable text”即可看到请求的内容。
由于本问题中的链路为“ng–>jetty A–>网关–>下游系统B”，可见jetty抓到的数据包，应该有与ng的交互，也有与网关的交互。所以可以进一步使用过滤器 tcp.stream == 7599 or tcp.stream ==7600,筛选出两段tcp连接请求。结合数据的流向和时间以及jetty A上的日志，可以定位到jetty A收到ng的请求到网关确认收到请求的事件很短，而与网关开始向jetty A发送数据的时间间隔很长，由此可见大部分耗时都在网关到下游系统B的耗时。然后截图甩给下游运维，啪啪打脸~