线上问题-OMS订单履约系统调用服务接口超时

1.现象: OMS订单履约系统调用服务接口超时(图1)

							图1 

2.调用链查看: 服务这段时间内存在一定的接口超时(图2)

                                                                                                  图2

3. 根据以往经验首先想到是服务有频繁FULLGC,查看服务是否频繁fullgc
   进入jdk bin目录下执行 ./jstat -gccause <进程id> <时间(单位毫秒)> (图3)
   

                                                                  图3
   

发现虽然有fullgc,但是7月4号启动的进程到7月9号, 总共fullgc次数为14次. 每天平均不到3次 (图4)

                                                                                                                                                                                                          图4

4.此时可以断定代码有问题,但是不足以致命,继续跟踪应用服务器性能监控
cpu: 发现9:22分左右有明显尖刺, 但是整体cpu负载在40%以下(图5)

                                                               图5

网络: 网络流量在9:22分左右有明显尖刺,说明有大量的数据流量占据网络IO(图6)

                                                                                                  图6

5.根据上述性能指标分析, 数据包数据来源估计是从DB读取的数据写入到内存,接下来我们看DB的性能指标
cpu: 9:22分左右cpu使用率在12%左右, 整体负载不高(图7)

                                                                                                                                                图7

iops: iops数据在9:22左右有尖刺, 说明此事有一波较大的瞬时流量打入到DB(图8)

                                                                                                                                                 图8

网络流量: 根据9:22分左右网络流量的尖刺, 平均每秒钟输出流量峰值为:46178.8kb, 说明此段时间内存在有问题的查询语句, 并且查询返回的数据量较大,也可能是瞬时并发较大,导致整体的网络流量出现尖刺(图9)

                                                                                                                                                   图9

6.根据上述问题,继续往下跟,既然知道了可能是存在大数据量查询的sql语句, 那我们就正好利用sql统计中的审计日志来进行分析
首先,选择时间段,生成审计日志(图10)

                                                                                                 图10

然后对审计日志进行分析,因为我想查找到底是哪个sql返回的行数较大, 所以分析维度选择返回行数
发现第一个sql执行了2次居然返回了6587993行数据, 第二个sql执行了218次,返回了1274864行数据,

sql1:

sql2:

7. 由此,问题的根本原因基本找到, 这两个sql语句对应的接口在设计上存在问题,第一个是操作日志表(因为历史原因,这个表是整个供应链记录操作记录的日志表), type为5的数据有10108830条记录(表中总共数据为18037716条), 第二个sql是每次查全部生效的类目数据, 但是查询次数较多,并且没有缓存, 穿透到DB, 这两个问题综合引起了整个网络流量的尖刺.
   8.后续解决方案

A.操作记录日志表及服务按照业务线拆分并做数据迁移.
B.梳理调用量较大并且数据变更频率不高的接口,完善相应的缓存机制.
C.一般问题出现时如果初步断定是网络问题的话, 都很有可能是系统问题引起的.需要进一步跟进具体产生此类问题的根源.
附:
第2步中细节部分
1.详细调用链路

上图中的调用行为分以下四种：
cs - Client Send : 客户端已经提出了请求。这就设置了跨度的开始。
sr - Server Receive: 服务器已收到请求并将开始处理它。这与CS之间的差异将是网络延迟和时钟抖动的组合。
ss - Server Send: 服务器已完成处理，并将请求发送回客户端。这与SR之间的差异将是服务器处理请求所花费的时间
cr - Client Receive : 客户端已经收到来自服务器的响应。这就设置了跨度的终点。当记录注释时，RPC被认为是完整的。

2.总上所述.服务整个的接口内部处理时间为ss-sr = 2019-07-09 09:23:21 199 - 2019-07-09 09:23:21 190 = 9ms, 但是返回给客户端的RPC耗时为cs-cr = 6s . 很大程度上断定这就是网路问题引起的, 但是一般问题出现时如果初步断定是网络问题的话,
都很有可能是系统问题引起的.需要进一步跟进具体产生此类问题的根源.