几天前，一个客户的主数据库实例发出警报。在诊断过程中，发现数据库故障是由一条运行缓慢的SQL引起的，但在彻底调查后，发现这种现象令人匪夷所思。

问题描述

MySQL实例已经超过五分钟没有更新了。这个报警信息的简单解释就是五分钟内无法获取这个实例的信息。

同时，开发者还反映，12月9日凌晨1点开始，部分数据库请求超时，直到报警信息出现后，业务才恢复正常。

问题排查

数据库系统使用袋鼠云easydb进行性能监控和告警，而EasyDB的服务器无法获取agent的信息，所以首要任务是检查easydbagent是否存活。

从上图可以看出，easydb进程工作正常。然后下一步就是从数据库和服务器层面进行检查。

2、MySQL错误日志

先看看MySQLerror日志里有没有错误信息的记录。登录主机，先了解MySQL的安装：

[root @ XXXXXX ~]# PS-ef | grepmysqld | egrep-vmysqld _ safe

.

.

/home/my 3304/bin/mysqld-defaults-file=/home/my 3304/my . CNF-basedir=/home/my 3304-datadir=/home/my 3304/data-plugin-dir=/home/my 3304/lib/plugin-log-error=/home/my 3304/log/alert . log-open-files-limit=65535-PID-file=/home/my 3304/run/mysqld。

.

.

通过查看进程状态信息，可以看到本地启动的mysql实例以及mysql的一些配置信息，并找到日志存储路径。

查看服务器上alarm实例的MySQLerrorlog，发现12月9日上午09: 16开始出现大量此类错误，一直持续到09: 48。

简要分析错误信息的含义：

[root@XXXXXXbin]#。/perror11

o错误代码11:资源暂时不可用

错误消息大致意思是资源暂时不可用，那么这个资源是什么意思呢？这是线。由此可以看出，数据库连接太多，有大量的主动连接请求。

从现象上看，有一些因素导致数据库连接数飙升，导致应用程序连接失败。

3.绩效指标

接下来我们来看看数据库和主机的具体性能指标和连接数是否真的飙升了，有没有其他异常指标与之相关？

系统中安装了Easydb，我们可以通过性能图清楚的看到具体哪些性能指标出现了问题。

通过查看报警实例的性能指数的曲线图，发现从12月9日凌晨1点左右开始连接数量增加，从09:16上午左右开始无法继续增加，直到09: 50左右基本释放。这与刚才看到的errorlog中的报错时间段基本一致。

和主机的TCP连接趋势图基本一致。

然后，接下来的任务就是找出连接数量猛增或者大部分没有释放的原因。继续观察其他绩效指标的图表。而其余的资源消耗却低得惊人。

数据库TPS、QPS和CPU利用率；

主机的CPU利用率和io:

期间的QPS和TPS极低，cpu和io资源完全闲置，所以期间的大部分线程应该是被阻塞的。

而其他几个关键性能指标，在09: 50左右，出现了与连接数趋势极端相反的情况，非常出乎意料。

此外，异常性能曲线还包括主机的io吞吐量和网络吞吐量等资源：

我们来分析一下09: 50之前的情况。简单来说，这段时间的性能数据就是连接数增加了，而资源利用率极低。

一般来说，导致这种情况的因素有两个：一个是锁等待；二是查询慢。两者的共性是部分SQL或事务造成链阻塞，最终全球或大范围阻塞。

然后看着锁等待着，

那么，这里的分析，问题基本可以定位为慢SQL。

4、MySQL慢日志

接下来，目标似乎变得更加清晰。就是找到有阻塞现象的慢SQL。

在09:00到10:00的慢速日志报告中，发现两个执行时间长的SQL。

直观来看，12月8日晚上09: 11左右执行一条SQL，执行这条SQL大概需要12个小时！在09年12月01: 02执行的FLUSHTABLE操作需要等待这个SQL执行完成。并且FLUSHTABLE被阻塞，这意味着任何后续的SQL操作都将被阻塞。

仅从这一现象，我们就可以理清前面发现的一些线索：

1.凌晨1点启动的应用程序报告了一个错误，并出现在FLUS中。

2.上午09点多出现的告警信息，是因为此时数据库已经无法再新建连接，agent进程无法连接mysql数据库，持续5s后出现告警

3.09点16分到09点50分左右这段时间，MySQLerrorlog报错与连接数曲线图吻合，说明09点16分thread资源耗尽，而09点50分左右阻塞者执行完成，连接数释放

4.两类曲线图变化反常关系解释，慢SQL从12月08日21点11分开始执行，经历45453s的时间，恰好是上午09点50分左右，此时SQL开始返回数据，逻辑读以及全表扫描指标急剧升高，同时还发现，这个SQL可能是有排序操作的

那么，这两个时间点，都在做什么？

与开发进行了简单的沟通，并且排查了easydb的日志。前一天晚上09点11分是一个开发人员的报表查询；而凌晨1点的FLUSH操作，是全备任务的一个执行阶段。

那么似乎是这个开发人员跑了个很烂的SQL导致的？

接下来的排查，发现情况好像并没这么乐观。

分析下这个SQL，语句如下：

执行计划如下：

从extras，我们看到，这个SQL使用到了临时表排序，并且貌似t_business_contacts表的关联列没有索引，而使用到了NestedLoop算法

那么，实际执行情况怎样？

开发人员反映，昨晚的执行，只用了2s不到的时间就获取到了结果，而刚才的执行情况也确实如此。

由于系统自运行以来，整体负载一直比较低，查询的数据量也不大，那么即使这个SQL语句有着不好的执行计划，执行的时间应该也是比较乐观的。但是从前面的现象来看，凌晨一点主库上发起全备任务时，这个SQL应该是还在执行。

再次查看了21:16前后的系统负载，CPU以及IO资源基本处于空闲，而QPS也极低，而12月08日也没有任何的慢SQL记录

如果只是1s多的时间就返回了数据，那么这个慢SQL从何而来？或许还有别的误操作，导致同样的SQL请求被发起，而这个相同的SQL卡在某个执行的阶段？从前面分析到的现象来看，这个SQL直到第二天上午09点50才开始返回数据。

仔细查看各项指标，发现几个系统指标在09号0点左右出现高峰，但是仍然无法解释09点16分执行的SQL被卡住

先保留这个疑问，这个SQL无疑是有着较大的性能问题的，我们先对其做个优化处理。

按照如下操作，添加两个索引:

altertablet_business_contactsaddindexidx_oi(org_id),ALGORITHM=INPLACE,LOCK=NONE;

altertablet_system_organizationaddindexidx_on(ORG_NAME),ALGORITHM=INPLACE,LOCK=NONE;

从新的执行计划，发现有了一些改观，没有了NestedLoop算法，而in查询取值池太大导致优化器没有选择索引，优化器仍然使用了总行数只有4000+的t_sup_qualifie_info表作为驱动表

接下来看下实际的执行效果：

执行效率有了接近40倍的提升！目前来看，优化效果还比较乐观

5、message日志

前面还提到一个CASE，就是业务恢复的时间，基本是和告警时间相吻合。从前面的发现来看，现在的问题就是为什么业务在数据库实例连接数释放之前就恢复了正常。

结合OSmessage日志，很快就解除了疑惑。上午09点16分开始的日志内容如下：

从这里可以看到，在目标实例不可用的时候，keepalived进行了主备的切换，因此，接下来的业务连接的都是原来的备实例。Easydb上看到现在的复制关系拓扑图如下：

6、SQL执行场景沟通

目前为止，问题的产生过程、告警原因、业务恢复过程，都能够有一个合理的解释了。那么现在的疑问就是，这个SQL为什么会这么慢？

尝试与开发人员进行沟通，看看这个SQL当时执行的场景如何。

开发人员表示，当时是使用的客户端工具进行的这个SQL的查询，人工查询后将结果汇总到Excel，而当时的查询过程不到两秒钟的时间。那么这个SQL实质就是一个每天进行的一个报表查询，这个流程已经进行了三个月，为何今天才出现问题？

结合SQL执行期间的业务压力以及系统的负载，基本很难构造出一个导致这个SQL执行如此耗时的场景。毕竟这个SQL执行不是数百上千秒，而是12h，这与前面手工执行验证的1.13s还是有着巨大差异的。

从数据库的慢SQL来看，有这样一个SQL执行慢，是肯定的，但是与开发人员的描述有极不相符，这个期间可能还是有些其他的异常情况，由于没有历史的showprocesslist数据，目前很难找到原因，看是否下次能够在某些情况下重现类似的问题。

根因分析

这是一个典型的连锁阻塞，过程如下：

1.昨晚某个时间点，某个客户端发起一个SQL请求，很长时间没有获得响应

2.凌晨的自动备份执行到FLUSHTABLE阶段，等待这个SQL执行完成

3.之后的SQL请求都被FLUSHTABLE阻塞

4.活跃连接数持续增加，导致Thread资源不可用，应用报错

5.EasyDBagent无法获取实例信息，持续5分钟触发告警；keepalived检测到主库不可用，自动切库

根因：

1.SQL执行效率太低（原因未知）

2.主库上有自动备份任务

后续

对SQL进行了优化之后，当天晚上关掉了所有主库的自动备份任务，防止类似的情况导致主库不可用；

至于SQL执行过程中到底发生了什么，确实很值得探究，但可惜的是，MySQL对历史性能数据视图支持的并不好，通过工具分析到的性能指标却又和这个SQL的执行情况完全相悖，或许如果能够构造出一个这样的场景，可能会有发现。