| 记一次突发mysq慢查导致Java应用数据库连接池耗尽、服务不可用的原因分析 | 您所在的位置：网站首页 › mysql数据库突然变慢持续了很久 › 记一次突发mysq慢查导致Java应用数据库连接池耗尽、服务不可用的原因分析 |
记一次突发mysq慢查导致Java应用数据库连接池耗尽、服务不可用的原因分析
|
文章目录
背景一、原因分析1、sql分析2、慢查原因3、问题表业务依赖梳理3.1、连锁店铺判断逻辑不严谨3.2、订单创建MQ消息处理时没有分布式锁幂等3.3、商家店铺订单数据存在异常
二、定位根因1、多方咨询2、苦尽甘来
总结
背景
某天上午在上班路上，忽然接到公司DBA电话告知我们业务出现大量SQL慢查询引起数据库物理机抖动，也影响到其他业务方（mysql 数据库，多个业务方数据库共用一台物理机）。由于在路上无法及时排查原因，和DBA沟通之后增加索引可以解决慢查询，于是先让DBA增加索引（先解决问题），后续再补线上增加索引工单流程和问题根因排查； 到公司之后发现问题影响面还挺大，虽然DBA临时添加索引解决了问题，但是出现问题期间还是有多个商家上报我们业务功能无法正常使用、页面无法正常展示数据。表象原因是一张表索引不够合理，由于一条慢SQL频繁执行，导致应用数据库连接池耗尽，从而影响Java应用无法正常对外提供服务。那为什么会突然出现慢查询呢？影响面还这么多广，带着这个疑问，我们一起深入分析… 一、原因分析 1、sql分析出现慢查询的SQL示例： SELECT id,shop_id,created_at,updated_at,record_type,row_key,operator_id FROM shop_set_record WHERE shop_id = 100766691 AND created_at 这段代码逻辑确实有问题，但是上方出现慢查的店铺是个单店，而非连锁店铺，所以问题产生原因不是这个，排除（代码逻辑问题本次也一并修复掉了，具体修复方案是保持店铺ID的查询和保存逻辑统一，不再展开）。 3.2、订单创建MQ消息处理时没有分布式锁幂等shopId=100766691 店铺根据订单创建时间查询在期间只有 1000+订单，而出现问题时快照产生了几十万，说明创建消息流量被放大了，而订单创建消息又没有分布式锁，可能会导致同一笔订单多个线程、大批量重试时同时进入代码逻辑最终产生大量快照数据(优化方案： 在创建消息中增加分布式锁幂等)；因为出了分布式锁之外，DB层我们也会有幂等校验，所以问题产生原因也不是这个，排除… 3.3、商家店铺订单数据存在异常继续排查问题店铺的快照设置表和订单的数据，产生了几点疑问： 1、出现慢查的店铺设置快照表（shop_set_record）字段创建时间相同，为什么updated_at不同？ 2、既然 updated_at 相隔大于1秒，那么理论上查询配置的时候应该很快就可以查询到，不应该有十几万的新增记录？（上面的并发场景如果只出现几十条可以说得通，出现了几十万那么并发就解释不通了） 3、 2021-10-27 07:00:00 - 2021-10-27 11:00:00 商家店铺产生订单数据量： 743 笔，而当时天网日志显示订单创建日志量有 579086 条记录，与实际订单量相差很大，是什么原因？ 4、为什么在10月26日系统处理到了5月份的订单创建逻辑？ 因为实际产生的订单量很少，但是我们处理的订单量很大，所以推测怀疑MQ消息重放导致订单流量放大。于是找运维中间件团队排查消息消息是否有重放过？ 既然问题出现在订单，那么为什么不找交易中心的同学咨询一下呢？脑海中忽然冒出这个想法，说干就干，拿着电脑坐到交易值班同学旁边一起排查，经过两个多小时的纠缠，终于疑团全部解开： 1、出现慢查的店铺设置快照表（shop_set_record）字段创建时间相同，为什么updated_at不同？ > 原因：创建时间取的是店铺设置时间，而更新时间是新增之后修改row_key 的时候的时间，所以DB中这条记录实际创建时间应该和updated_at相近；详见流程图： 2、既然 updated_at 相隔大于1秒，那么理论上查询配置的时候应该很快就可以查询到，不应该有十几万的新增记录？（上面的并发场景如果只出现几十条可以说得通，出现了几十万那么并发就解释不通了） > 原因：在出现问题期间有10月7号的订单创建消息流量，而商家店铺创建设置的时间是 10月8号，导致10月7号的订单去查询配置查询不到，一直在创建新的店铺设置记录；所以历史订单创建多少笔就会导致快照设置插入多少次（原因同上）； 3、 2021-10-27 07:00:00 - 2021-10-27 11:00:00 商家店铺产生订单数据量： 743 笔，而当时天网日志显示订单创建日志量有 579086 条记录，与实际订单量相差很大，是什么原因？ > 原因： 商家店铺正常在我们系统下单的数据只有 700+笔，但是商家通过交易open接口将历史订单同步到我们系统的数据量很大，商家系统历史订单同步到我们系统时订单号是根据我们规则生成的，但是订单创建时间是商家历史订单的创建时间；示例：订单号：X20211026143847041206239（订单号前12位数字是日期时间格式），订单下单时间记录的是商家历史订单的时间：2021-01-17 16:53:28 4、为什么在10月26日系统处理到了5月份的订单创建逻辑？ > 原因： 交易中心有同步历史订单开放接口，当商家调用这个接口创建新的订单时创建时间记录的是商家历史数据时间； 1、在遇到困难瓶颈的时候，及时寻求帮助也是很好的策略。 2、合理利用自己的时间，紧急、重要四象限的事情是随着时间可以调整的。 3、产生问题总有根因，一定要有深挖原因、不达目的不罢休的精神，付出努力总会有收货。冰山模型，看到的表现不一定是问题的根因，比如这个问题增加索引只能解决慢查，而内部的代码逻辑问题得到优化之后才算问题真正解决； |
而在此时，发生了一个令人更加头痛的事情：生产环境日志丢失了。由于当时手上有其他紧急的事情需要处理，导致上面未解之谜搁置了一段时间。十几天后有时间了想再去排查原因时，发现应用已经重新发布原有的docker容器被销毁、日志系统也仅保留7天日志。想要排查根因，却面临无日志可查，但是不能放弃，因为如果问题根因没有解决，那么问题就有再次复发的可能，一定要找到根因并解决。
消息没有被重放过，那会不会有人手动调用线上接口修数据了？ 
一喜一优，本来以为找到原因了，结果告知不是出现问题的这家店铺。因此上面两个原因都排除…
至此，长达十多天的问题原因排查终于都有了答案，虽然花费了时间，但是收获了成长，是值得的。 
【本文地址】