菜鸟排查数据库异常的事 - 快车库

这件事情起源于上个月做的微信公众号项目，在项目上线初期，运行平稳，数据库并没有出现异常。

问题出现在微信公众号推送活动消息后，数据库cpu直接满载,而且连接数到达了设置的最大值，新用户打不开或者打开很慢。当时监控显示的情况很糟糕。

面对这样的情况,运维的兄弟多开了几台tomcat试图来缓减，当时后来的情况是并没有luan用，新开的服务器的负载很快也变的很高，情况依旧。而且当时的情况也很赶，各方面都在催，我们选择了将数据库读写操作量大的用户表的操作转移到redis中这样一种方式避开对数据的操作，上线后情况得到改善，线上的事情告一段落，后面就是排查问题的阶段了。

到了秋后算账的时间，要排查问题的所在，首先抓取了一些可能有用的日志，当时的日志情况是这样的。

SEVERE: Servlet.service() for servlet [web-dispatcher] in context with path [/******] threw exception [Request processing failed; nested exception is org.mybatis.spring.MyBatisSystemException: nested exception is org.apache.ibatis.exceptions.PersistenceException:
### Error querying database.  Cause: org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 5000, active 73

这个日志所反映的问题，而且考虑到出问题的时候都是在并发量大的情况下，第一反应是druid的连接池出了问题（在上线的时候也是这么认为的，运维哥们专业黑druid　500年啊...），由于连接池没有及时回收无用的连接，导致连接池的连接数达到了maxActive（设置的连接池最大使用连接数），使新的连接一直处在等待中，直至等待时间超过了获取连接最大等待时间从而抛出异常。从这一角度出发，在做单元测试的时候，将druid的timeout的时间大大的延长，并将清除无用连接的等待时间缩短，寄希望于druid的连接池处理大量连接时将无用的连接释放掉，在跑单元测试的时候确实跑出异常的情况有所改善，抛出异常的时间延后了，给人的感觉是稳定跑的时间长了，但是从实际情况来说，只是连接等待时间的阈值提高了，对问题的解决没有帮助，从这一方面来排查的结果以失败告终。

由于原先装的是Mysql的衍生版本mariadb，运维兄弟说排查下是不是mysql自身的问题，就给配了一台装了原版5.6的服务器。把测试数据库上的数据dump到了5.6里，然后进行压测，在监控上，同样是数据库连接数很高，而且cpu基本上满载了，问题没有得到改善，可以认为这个问题基本与数据库的版本无关。

断断续续的测试了几天，总是不得要领，事情到这里我这个菜鸟就感觉无从下手了。问了师傅，他老人家说从慢查询日志上看看情况，其实很久以前他就说过，只是我看了以后也没看出啥问题(菜鸟就是菜鸟啊)，当时看日志只关注了sql语句，只是时间确实很长，但对于为啥这么慢却一直不知道从哪里入手。这期间，也优化过一些东西，比如把查询的时候UNION的操作从原来在数据库级别搞到在后台进行，在数据库级只是进行select的操作，union的操作人工的进行，也有很大的提升，但是由于在慢查询日志中大量的是单条select的查询操作，union只占了一小部分，所以最根本的问题没有解决，测试的时候负载依旧会很高，然后超时导致错误率很高。

回头想想，几天前犯了个大错误，看日志只片面的看一部分，没有对各个参数有所了解，漏了重要的一些参数。某天睡醒是后看了慢查询日志，发现以前没注意到的一个参数，就是Rows_examined，日志每条信息中它的值都很大，可以认为是目标表里的所有数据的数目了，换句话说，在查询的时候，没有任何优化做了全表的检索，时间耗在了这里。这时候就有了一点点的思路，既然问题出在查询的时候特别慢，那么在数据库中对查询的性能影响很大的索引就成为了重点关注对象。

Query_time: 4.107505  Lock_time: 0.000154  Rows_sent: 1  Rows_examined: 259017

有了这样一个初步的排查的目标，下面就是验证阶段了，看了不同服务器上数据库的表，发现建立的索引都不一致，有些是建立正确的，有些是错误的（造成不一致的原因可能是某个时间看到了发现了问题，就改正了这一错误，但是当时没有将所有的数据库改过来，测试时候用的服务器仍旧是有问题的）。验证的话就是简单的对比实验：代码和压测的线程数和服务器等条件都一致，唯一的不同就在于数据库索引的不同，一个是正确的索引，一个是出问题时候的索引，进行压力测试，在测试期间利用jstack抓取进程，并对日志进行分析。结果如下，通过对比，基本得出是因为索引的问题了，如果后面还发现了这样的异常，那就另外排查了。

mysql> explain select *  from   user_info where  openid = 'aaaaaaaaaaaaaaaaaaaaaaaa';
+------+-------------+-------------------+------+---------------+------+---------+------+---------+-------------+
| id   | select_type | table             | type | possible_keys | key  | key_len | ref  | rows    | Extra       |
+------+-------------+-------------------+------+---------------+------+---------+------+---------+-------------+
|    1 | SIMPLE      | lottery_user_info | ALL  | NULL          | NULL | NULL    | NULL | 1182759 | Using where |
+------+-------------+-------------------+------+---------------+------+---------+------+---------+-------------+
1 row in set (0.01 sec)

mysql> explain select *  from   user_info where  openid = 'aaaaaaaaaaaaaaaaaaaaaaaa';
+------+-------------+-------------------+------+---------------+--------------+---------+-------+------+-----------------------+
| id   | select_type | table             | type | possible_keys | key          | key_len | ref   | rows | Extra                 |
+------+-------------+-------------------+------+---------------+--------------+---------+-------+------+-----------------------+
|    1 | SIMPLE      | user_info | ref  | openid_index  | openid_index | 98      | const |    1 | Using index condition |
+------+-------------+-------------------+------+---------------+--------------+---------+-------+------+-----------------------+
1 row in set (0.01 sec)

对于这样一个状况的排查直到初步得出结论，感觉自己走了好多的弯路，选择了从上倒下的排查这样一个步骤，当初如果选择从最基础的数据库设计和语句方面入手的话，可能会节约很多的时间。不过排查的时间久也有好处，最起码学习了很多新知识(自我安慰下)。

学识浅薄，如果有不对的地方，烦请不吝赐教，谢谢。