我的博客

【线上排查系列】线上系统接口超时复盘

2022/04/21 线上排查 共 1726 字，约 5 分钟

今天突然收到运营人员反馈系统出现了故障，登录系统后，发现部分接口调用超时。

下面对本次故障进行复盘。

故障描述

运营系统订单模块功能异常，报错信息有服务器异常、接口超时，其他模块功能正常。

故障排查

由于只影响了订单服务，所以我们查看订单服务的系统日志，快速定位到异常日志，报错信息如下（截取部分并脱敏处理）：

 SELECT * FROM jf_order_detail2021 
 WHERE  (order_detail_no = ? AND pay_time >= ? AND pay_time <= ?)
      ...  at org.springframework.jdbc.support.SQLStateSQLExceptionTranslator.doTranslate(SQLStateSQLExceptionTranslator
.java:120)
org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java
:73)
com.plhs.order.biz.service.cloudimpl.OrderCloudServiceImpl.updateOrder(OrderCloudServiceImpl.java:76)
        at org.apache.dubbo.common.bytecode.Wrapper28.invokeMethod(Wrapper28.java)
Caused by: com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 60000, active 50, maxActive 50, creating 0, runningSqlCount 26 :

我们可以发现，直接原因是数据库连接超时，最大连接数是50个，当前连接数是50个，已经没有新的可用的连接，当前正在执行的SQL有26个。

到底什么原因导致了数据库连接超时呢？

我们继续排查日志，发现 jf_order_detail 表短时间内有大量的查询操作，具体SQL如下：

 SELECT * FROM jf_order_detail2020 WHERE  (order_detail_no = ? AND pay_time >= ? AND pay_time <= ?)
 SELECT * FROM jf_order_detail2021 WHERE  (order_detail_no = ? AND pay_time >= ? AND pay_time <= ?)
 SELECT * FROM jf_order_detail2022 WHERE  (order_detail_no = ? AND pay_time >= ? AND pay_time <= ?)

问题分析

先说下jf_order_detail表 的设计背景，该表是早期设计的，由于每年的订单量较大，所以设计者按照时间范围进行分片，每年度一张表。每次查询的时候带上时间分片键。

但是为什么会同时查这三张表呢？我们需要看下代码的具体逻辑，分析如下：

由于查询订单的时候只有订单号，没有时间范围，开发人员把时间范围初始化为最早时间到当前时间，也就是2020年-2022年。所以走了全库表路由，每张表都查询了一次然后汇总结果。

如果仅仅这个原因的话，性能不至于这么慢啊，我们继续看另一个字段 order_detail_no，先看下执行计划

EXPLAIN SELECT * FROM jf_order_detail2020 where order_detail_no = '1'

发现该字段并没有建立索引，type = ALL，全表扫描，扫描行数几百万条。这才是拖垮MySQL的罪魁祸首。

问题解决

给order_detail_no字段建立索引，并优化代码逻辑把时间范围缩小，能定位到具体年份。

当然，这个系统是遗留的老项目了，出现问题的代码已经很久没变动了，一般业务并不会执行此处逻辑，只有第三方个别业务会执行此处逻辑，由于并发量提升了，问题也就凸显出来了。

所以在设计之初，我们就要考虑到业务的查询场景，并尽早设计好索引，同时还需要加强对接口和数据库的性能监控。

文档信息

搜索

    Table of Contents