记一次延时问题的排查

 

问题

系统对请求的响应延时较长

注：改系统有一定的并发性，且对时效性有一定的要求

 

相关数据流转

1、我写的转发服务接收到系统的请求，并将数据转化成真正提供服务的服务方（下文简称为“服务方”）需要的格式

2、发送请求至服务方

3、接收服务方的响应

4、将服务方的响应转化为系统需要的响应，并返回给系统

 

直接原因

查看日志，发现在业务高峰期（并发量相对较高）请求处理普遍较慢，且我看了下主要耗时发生在等待服务方的响应那里

遂跟服务方一起对了一条数据，对方表示该条数据他们处理地很快，经过详细比对，发现我这边发出请求的时间，与他们接收到请求的时间相差比较多

 

深入追查&问题解决

1、优化日志，在一行内打印关键时间戳和耗时时长

2、模拟业务高峰期的请求量

3、确认之前的初步判断是否正确

（1）导出大量耗时数据，导入 excel 分析

（2）导出大量耗时数据与服务方比对

（3）抓包分析，找到请求的准确发出时间

4、与服务方协调，让他们也同步排查他们那边的问题

5、步骤 3 与 4 同步进行，最终服务方确认了是他们的问题

 

总结

如果再来一次，我这边应该如何处理问题

 

预防

出问题之前，即写代码时，就应该注意到的点

1、日志配置

    保留时长

        没有强制要求的话，不删日志；如果考虑到空间问题，可以设置为保留3个月

    日志级别

        调到 debug 进行调试与日志输出

    打印第三方服务中的日志

        调用的关键的第三方的服务，最好将其中的日志也打印出来，方便以后排查问题

2、在日志中记录运行耗时（对时效性要求比较高的服务）

    对时间敏感的程序，需要记录时间戳和计算总的和重要方法的运行时长，最好在一行日志中打印出来，且这行日志中需要有整个日志文件中都不会出现的字符串，这样方便以后排查问题时，将所有记录运行时长的那些行导出到一个文件中

3、restTemplate 对于高并发的坑

参考：https://www.cnblogs.com/jimw/p/9037542.html

 

事情发生后

问题出现后，如何排查

1、tcpdump 抓包，拖入 wireshark 分析

本次，客户端发出请求与服务端接收到请求的时间相差比较多  这时，需要考虑是不是客户端的时间戳不准确，因为调用了第三方的 jar 包，会经过很多其他代码（我调用了第三方的 jar 包，要经过别人的一些代码才能发出请求，但是那些代码里，我打印不了时间，所以，请求的实际发出时间可能跟现在在日志里看到的有出入）或者说性能参数没有调好（restTemplate 的相关参数）导致的阻塞 要确定具体的请求发出时间，就要抓包，即准确获取数据经过网卡的时间点

我的博文：https://www.cnblogs.com/stone94/p/12357782.html

2、导入 excel 分析

把日志导入到 excel 中分析

将日志文件中的数据导入到 excel 中进行分析，用分隔符的方式导入

导入方法可自行搜索

 

没能解决的话

本级解决不了的异常，应该及时上抛

及时邮件反馈

    在项目中，有解决不了的问题，及时发邮件反馈给领导