记一次接口超时问题排查

今天生产环境突然出现一个老接口的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的耗时。然后截图甩给下游运维,啪啪打脸~

上一篇:如何使用schematics快速创建全新的SAP Spartacus Storefront并启用SSR


下一篇:通过 Feature Level 动态控制 SAP Spartacus 的页面显示