11

记一次 MySQL 数据库问题排查

 3 years ago
source link: http://kohpoll.github.io/blog/2016/01/06/about-a-sql-debug/
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.

最近遇到应用频繁的响应缓慢,无法正常访问。帮忙一起定位原因,最后定位到的问题说起来真的是很小的细节问题,但是就是这些小细节导致了服务不稳定,真是细节决定成败。这里尝试着来分享下,希望对大家有所帮助。

问题 1:占着茅坑不拉屎

遇到问题首先要看的还是服务器错误日志。

错误日志中看到频繁有这样的一个异常报错:Error: ER_CON_COUNT_ERROR: Too many connections。这个报错是因为数据库的所有连接被客户端都占有了,没有空闲的连接可以使用。MySQL 默认的最大并发连接数是 100,然而我们的应用这边最多可能的并发也就 30~40 个任务,怎么也不太可能报这样的错误,推测很有可能是代码里面建立连接后没有及时的进行关闭。于是我们重点看了下执行 SQL 部分的代码,大概是下面这样(使用了node-mysql库):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
var mysql = require('mysql');
// 建立连接池
var pool = mysql.createPool({
host: 'host',
user: 'user',
password: 'password',
database: 'db'
});

exports.query = function(sql, cb) {
// 从池子里面取一个可用连接
pool.getConnection(function(err, connection) {
if (err) throw err;
// 执行sql
connection.query(sql, function(err, rows, fields) {
if (err) {
return cosole.error(err);
}
cb(rows);
});
// 释放此连接
connection.release();
});

};

刚开始我还真没看出来有什么问题,后来仔细读了 node-mysql 的文档及这个 issue,终于发现了我们的写法是有问题的。

再次看看上面的代码,pool.getConnection 后我们执行 connection.query,然后没等 SQL 执行完,直接调用了 connection.release,由于 JavaScript 的异步特性(虽然 SQL 可能很快就执行完,但是我们也必须在 connection.query 的 callback 里面才明确的知道 SQL 执行完了),这个时候此次连接是不会被释放的!代码里面所有的 SQL 执行都调用到这个函数,这意味着我们占着一堆数据库连接不释放,这时不断的有其他数据库连接过来,直接导致其他连接被阻塞,抛出连接太多的异常。这真是典型的“拉完不及时让坑,占着茅坑不拉屎”的行为。所以,我们一定要在 SQL 执行完成后就将连接及时进行释放。因为 SQL 执行一般是非常快的(零点几秒),如果我们执行完后不释放,在同一时间产生很多数据库连接时很有可能导致连接被阻塞,产生连接过多的异常。于是我们对代码进行了如下修改:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
exports.query = function(sql, cb) {
// 从池子里面取一个可用连接
pool.getConnection(function(err, connection) {
if (err) throw err;
// 执行sql
connection.query(sql, function(err, rows, fields) {
// 释放连接(一定要在错误处理前,不然出错的时候也会导致该连接得不到释放)
connection.release();

if (err) {
return cosole.error(err);
}
cb(rows);
});
});

};

也可以用更简单的写法 pool.query,这个方法内部会在合适的时机来释放连接,不用我们手动操作。

完成此次修改后,这个异常没有再复现,但是响应缓慢的情况依然没有得到缓解。

问题 2:一条 UPDATE 引发的血案

我们再次查看了错误日志,发现了另一个异常报错:Error: ER_LOCK_WAIT_TIMEOUT: Lock wait timeout exceeded; try restarting transaction。这个报错就非常令人费解了,原因是锁等待超时,当前事务在等待其它事务释放锁资源造成的。

我们先大概说下什么是事务(transaction)。事务应该具有 4 个属性:

  • 原子性(事务作为整体执行,操作要么全部执行、要么全部不执行)
  • 一致性(事务应该确保数据库状态从一个一致状态转变为另一个一致状态)
  • 隔离性(多个事务并发执行时,一个事务执行不影响其他事务执行)
  • 持久性(事务提交后,对数据库修改应该永久保存在数据库中)

对于隔离性,还会分出多个隔离级别:

隔离级别 脏读 不可重复读 幻读 未提交读 可能 可能 可能 已提交读 不可能 可能 可能 可重复读 不可能 不可能 可能 串行化 不可能 不可能 不可能
  • 脏读(Dirty Read):A 事务读到 B 事务未提交的修改。
  • 不可重复读(NonRepeatable Read):A 事务还没有结束时,B 事务也访问同一数据。在 A 事务的两次读取之间,由于 B 事务的修改,A 事务两次读到的数据可能是不一样的。
  • 幻读(Phantom Read):A 事务对一个表中的数据进行了修改,这种修改涉及到表中的全部数据行。同时,B 事务也修改这个表中的数据,这种修改是向表中插入一行新数据。操作 A 事务的用户发现表中出现了 B 事务插入的行,就好象发生了幻觉一样。

MySQL 默认的级别是 REPEATABLE READ(可重复读),这表示在 MySQL 的默认情况下,“脏读”、“不可重复读”是不会发生的。这就需要在更新的时候进行必要的锁定(InnoDB 是采用行级锁的方式),从而保证一致性。需要注意的是 InnoDB 的行锁是通过给索引上的索引项加锁来实现的,这个特点意味着:只有通过索引条件检索数据,InnoDB 才使用行级锁,否则,InnoDB 将使用表锁!

我们数据库表是 InnoDB 引擎的表,而 MySQL 的 InnoDB 引擎是一个支持事务的引擎,其默认操作模式是 autocommit 自动提交模式。什么意思呢?除非我们显式地开始一个事务,否则每个查询都被当做一个单独的事务自动执行。

回到上面的报错,错误日志里抛出异常时执行的 SQL 语句,都是类似这样的一条 UPDATE 语句:update testScore set status=1,executionId='946012' where token='f7900c40-8f4b-11e5-b2f1-6feca76a1bf5'

问题产生的原因可以这样来描述了:我们在执行 UPDATE 语句时,MySQL 会将其当成一个事务,对表的行进行锁定,这时又有其他连接进来要 UPDATE 同样的表或者 SELECT 这张表时就必须等待锁资源,而这个等待时间太久,导致超时了。

什么?一个 UPDATE 语句居然会这么慢?这我简直不能接受啊!那我只能看看为啥这个语句如此慢了。

查看慢查询(slow_queries.log)日志里面对应的查询信息:

1
2
# Query_time: 56.855324  Lock_time: 48.054343 Rows_sent: 0  Rows_examined: 29400
update testScore set uiTaskId=81041 where token='e7d7d8f0-8f4b-11e5-99be-9dfbb419755e';

这样一条 UPDATE 语句花了 56 秒,扫了 29400 条表记录。看到这样的执行日志,也大概猜到原因了,没有为查询字段 token 加索引!这样 MySQL 在进行 update 操作时不会走行锁,直接锁定了整张表,而这个 update 语句本身也够慢(扫了全表),那并发多个 update 更新时导致了等待锁超时。

给 testScore 表的 token 字段增加了索引,终于,这个异常不再复现,响应时间开始回归正常。

本文采用 知识共享署名 3.0 中国大陆许可协议,可自由转载、引用,但需署名作者且注明文章出处 。


About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK