一次MySQL数据库生产事故以及问题定位

概要

本文记录了作者最近遇到的一次MySQL数据库生产事故，以及怎么定位BUG的整个过程。

事故描述

随着业务发展，数据库的表会出现爆炸式增长。最近根据一个客户反映，我们的一个业务接口，响应返回的速度越来越慢，随后两天，其他客户也相继反映同样的问题。终于在第三天，DBA反映我们的MySQL数据库“爆了”，CPU的使用率达到2000%，最后这个接口瘫痪了。

问题定位

添加日志

先收窄范围。收到BUG的报告时，我们团队就通过StopWatch在业务接口的关键代码里，增加了耗时的监控。很明显地，在入口处的selectLog性能很低，初步锁定问题。

2020-08-08T16:02:34.437 | [http-nio-8080-exec-163] | [INFO] | MServiceImpl | doUpdate:StopWatch 'xxxxxxx': running time (millis) = 7406
-----------------------------------------
ms     %     Task name
-----------------------------------------
07401  100%  selectLog
00000  000%  redisOper
00002  000%  updateLog
00001  000%  select1
00001  000%  select2
00001  000%  AsyncOper
00000  000%  MqOper

分析问题

系统主要采用了继承tk.mybatis.mapper.common.Mapper的方式，来实现对数据库的操作。对于表tb_m_log，字段number（手机号码）和t_id（事务ID）可以确定一个业务日志。因此初步方案是建立组合唯一索引来优化这个查询。

public interface MLogMapper extends Mapper<MLogDO> {
    @Select("SELECT * FROM tb_m_log where number = #{number} and t_id = #{trancationId}")
    @Results(id = "MLogDOMap", value = {此处省略})
    MLogDO selectLog(@Param("number") Long number, @Param("trancationId") String trancationId);
}

后续观察

在压力测试环境（用于模拟生产环境，测试系统性能），通过JMETER做了压测，查看结果和数据库的执行计划，都证明增加索引的方案是没问题的。但是由于这日志表已经达到了500w的数据量，最后选择了在业务量低的深夜执行了创建索引的操作。

随后生产执行了创建索引的脚本，再次观察日志如下，效果不明显。开发团队陷入了沉思……

2020-08-09T01:02:34.437 | [http-nio-8080-exec-161] | [INFO] | MServiceImpl | doUpdate:StopWatch 'xxxxxxx': running time (millis) = 6406
-----------------------------------------
ms     %     Task name
-----------------------------------------
06401  100%  selectLog
00000  000%  redisOper
00002  000%  updateLog
00001  000%  select1
00001  000%  select2
00001  000%  AsyncOper
00000  000%  MqOper

DBA介入

后面根据DBA的报告，我们的数据库CPU使用率飙升到2000% 事态变得越来越严重。我们把涉及的SQL都提交给DBA，等待DBA的建议。最后DBA在慢查询日志里，找到了这些SQL。DBA通过查看这些SQL的执行计划，发现根本没有用到索引……

SELECT * FROM tb_m_log where number = 13800000001 and t_id = 'do^Hd%';
SELECT * FROM tb_m_log where number = 13800200001 and t_id = '1d*kd0';
……

揭开真相

团队决定复盘一下生产的数据库表结构，跟其他环境的对比一下。最后发现生产上的number字段竟然是varchar类型的，然而测试库的是bigint，代码维护的number是java.lang.Long 导致传入参数的时候，没有加上单引号，从而导致两侧的环境表现不一致，引起索引失效。

CREATE TABLE `tb_m_log ` (
  `id` bigint(20) unsigned NOT NULL,
  `job_code` varchar(50) NOT NULL,
  `number` varchar(50) NOT NULL,
  `t_id ` varchar(50) NOT NULL,
  ……省略
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
-- 生产

CREATE TABLE `tb_m_log ` (
  `id` bigint(20) unsigned NOT NULL,
  `job_code` varchar(50) NOT NULL,
  `number` bigint(20) unsigned NOT NULL,
  `t_id ` varchar(50) NOT NULL,
  ……省略
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
-- 测试

修复后性能如下

2020-08-11T10:02:34.437 | [http-nio-8080-exec-61] | [INFO] | MServiceImpl | doUpdate:StopWatch 'xxxxxxx': running time (millis) = 6
-----------------------------------------
ms     %     Task name
-----------------------------------------
00001  100%  selectLog
00000  000%  redisOper
00002  000%  updateLog
00001  000%  select1
00001  000%  select2
00001  000%  AsyncOper
00000  000%  MqOper

小结

通过这次事故，我们发现了团队的管理漏洞，SQL脚本的管理也是顺利上线的前提保障，不容忽视。另外使用Docker等容器化技术也可以作为后续优化方向。希望本文能帮忙大家在以后遇到生产问题时，能快速定位以及解决。

Wechat: