记一次 Lindorm 查询超时问题


theme: smartblue

负责的一个 IOT 平台,在一天早上突然发现 MQ 堆积严重(1小时堆积上涨百万左右)。之前也遇到过这种问题,基本都是因为依赖的 OSS 变慢导致,有时因为其他业务把 OSS 带宽打满,有时因为 OSS 本身在并发量大的情况下会做限流措施。

问题排查处理

到公司之后先查看了相关的日志(由于 Lindorm 超时严重已经有很多 ERROR 告警),根据告警日志发现是数据库(Lindorm)的连接池满了(使用的 durid),错误堆栈基本都是下面这样。

org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException: 
### Error updating database.  Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Failed to obtain JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 30000, active 20, maxActive 20, runningSqlCount 2 : select  ts
                ,metric
                ,val
        from    monitor_metric
        where   app_bind_rel_id = ?
        and     metric in
         (  
            ?
         ) 
        and     ts >= ? and ts <= ?
        order by app_bind_rel_id, metric, ts
runningSqlCount 1 : SELECT  app_bind_rel_id,oss_key,lng,angle,gmt_create,speed,lat,ts  FROM data_track_point 

WHERE (app_bind_rel_id = ? AND ts > ? AND ts < ?)
runningSqlCount 6 : SELECT ts AS id, concat(?, CAST(lng AS varchar), ?, CAST(lat AS varchar), ?) AS coord, ts
FROM data_track_point
WHERE app_bind…

从错误上也很容易看出来问题,数据库连接池已经被用满,无法获取到 JDBC 连接。连接池被用满的情况,巨大多数情况都是因为慢 SQL!于是根据之前预埋的日志查看了下 Lindom 相关 SQL 的执行时间,果然跟猜测一致,查询耗时 4-5W ms,写入耗时 2-3W ms,平时查询、写入基本都是 10 ms 以内。这么慢连接池不满才怪。

首先想到的是 Lindorm 的问题(这里应该打自己一个嘴巴,毕竟是阿里云的成熟服务,出问题的几率比自己服务出问题的几率要小很多,在这里浪费了不少时间),于是找 Lindorm 的同学咨询 Lindorm 集群是否有问题。因为当时为了测试建了个临时表,里面只有一条数据,查询起来也要很久。

Lindorm 的同学介入后,发现有慢 SQL 让业务自查。但是我们最近也没有发版,所以一时的确也找不到问题所在。Lindorm 同学通过监控平台发现对 data_track_point 表的读取量有大幅的增加,让看下是否查询方式有变更或者输入参数有较大变化。

排查了半天实在还是没有头绪,查看了这个表所有的相关读取,都没看到有啥问题(主要服务的确没有做过变更)。

于是咨询 Lindorm 的同学是否有 dbservice 那种 SQL 限流能力,没有给答复(应该暂时不具备)。后来说可以尝试把问题表隔离出去,从而不影响整个集群的服务。于是先执行了这个表的隔离操作,但是隔离完发现没啥效果,或者说有效果有限吧,响应变得忽快忽慢。拉群之后答复应该是因为使用了轻客户端(SQL)的方式,导致隔离策略没有生效,Lindorm 在这种使用方式下对请求的路由是随机选择节点下发,下发到有问题表的节点上就很慢,到其他节点上就很快。

处理恢复

于是业务侧考虑开始限流,对于端上来的 HTTP 请求处理很简单。由于接入了 sentinel,在 sentinel 里配置下限流规则就立马生效了。这里必须吹一波 sentinel,强烈建议有线上业务的一定要接入,救命的法宝。如果没有 sentinel 只能改代码发版,现实是发版都不一定解决,因为 Lindorm 响应极慢,在应用启动时候获取连接特别慢。

但是除了这里还有 Spring Event 分发做触发的(其实这里的请求没啥问题),好在这里通过一个曲折的配置也可以禁用掉。

所有流量限掉后, Lindorm 集群开始恢复。

问题定位

业务恢复后开始想办法找到真正的原因,开始一直怀疑是 Lindorm 的某个节点有问题,导致了慢查询,从而把集群拖挂。因为除了最开始的慢 SQL,后面所有请求的 SQL 都是慢 SQL 了,的确不好区分到底是谁的问题。也考虑过是否因为数据量变大之后导致的查询雪崩,但其实这种一般都是线性的或者是有预兆的变慢,而我们这个就是突然完全崩掉,应该也不是这个问题。

最后在看消息的时候,发现昨晚端上有过设备的全量 OTA 升级。进而怀疑是否可能是这个导致,而且发版时间点跟 Lindrom 的读取量暴涨可以对应上。于是仔细的排查了上面被限流接口的输入参数。发现开始时间有输入为 0 的情况,而这个接口会使用开始时间对 data_track_point 做范围查询,到这里基本就可以定位问题了。

咨询端上同学为啥开始时间会传 0 ?告知是因为 OTA 之后设备的系统时间会被重置为 0 。但之前也有过很多次 OTA,为啥只有这次又问题呢?主要因为之前这个数据用 MySql 存储了 1 个月,切换 Lindorm 之后存储了 3 个月(且使用了冷存储特性),Lindorm 相比 MySql 查询不是他的强项。而且查询这么大范围的数据,对所有数据库都是噩梦。

血泪教训

  • 对端上的输入一定要有校验
  • 涉及到对大表的范围查询一定要谨慎、谨慎再谨慎
  • 对线上业务一定要做好限流、降级能力建设,遇到此类问题先做限流、降级,保证业务大面不受影响
  • 对各个模块尽量做好隔离,在定位问题的时候比较方便,想要限流也比较容易

这是一个从 https://juejin.cn/post/7368820207592898569 下的原始话题分离的讨论话题