本文介绍了一次MySQL查询缓慢的问题排查过程，通过分析show processlist和使用mysqladmin debug命令，最终定位到导致阻塞的原因，并解决了问题。
做为一款轻量级数据库软件，MySQL在使用过程中遇到访问速度慢，或者无法响应这类的问题，解决方式基本都有定式，一般第一反应都会是登录到MySQL, show processlist看看当前连接状态。
虽说简单，但show processlist显示的信息确实是相当有用，有一回，三思收到反馈说MySQL查询很慢，于是，赶紧登录到mysql中，执行show processlist查看当前连接信息：
一堆的Locked，怪不得慢啊，阻塞的时间不短了，十几分钟。
通常来说存在Locked就说明当前读写操作存在被阻塞的情况，一般我们看到锁都会下意识认为是由于写阻塞了读，上面的结果看仿佛也符合这一特征：只有一条UPDATE，而无数条的SELECT。猜是必须的，但不能瞎猜，这毕竟是线上系统，就算想杀连接的线程，也是要杀掉造成阻塞的那个，不能把所有Locked的全杀了，不然DBA本人很快也要被人杀了，因此具体情况如何还是需要继续分析。
从show processlist查看到的信息来看，UPDATE的语句是很简单的，分析a的表结构，该表为MyISAM表，ID为该表主键，该条更新应该能够瞬间执行完，即使系统繁忙也不应该，而且通过查看当前的系统状态，整体负载很低，iostat中看I/Owait几可忽略，该写操作不太可能这么长时间都没有执行完。
这个时候再分析show processlist中显示的信息，发现id 123890的语句执行时间最长，肯定是在该UPDATE语句之前执行的，通过show full processlist查看语句详表，看到该查询也访问到了a表，经此分析，应该是该语句长时间的读阻塞了写，而被阻塞的写操作由于处于最优先处理队列，又阻塞了其它的读。
不过这些都还只是我们的推论，考虑到线上系统服务的可靠性，最好还是能找到更确切的证据，而后再做操作。
mysqladmin命令有一个debug参数，可以分析当前MySQL服务的状态信息，同时也可以用来帮助我们定位当前锁的详细情况，这里我们通过该命令分析一下当前MySQL服务的详细状态，执行mysqladmin命令如下：
[code="linux"]
# mysqladmin -ujss -p -S /data/3306/mysql.sock debug
Enter password:
[/code]
debug会将状态信息生成到mysql的错误文件，一般锁的信息都会保存在最后几行，这里我们在操作系统层error log最后几行：
[code="linux"]
# tail -10 phpmysql02.err
Thread database.table_name Locked/Waiting Lock_type
2 hdpic.t_wiki_zutu Waiting - write Highest priority write lock
123890 hdpic.t_wiki_zutu_category Locked - read Low priority read lock
123890 hdpic.t_wiki_zutu_photo Locked - read Low priority read lock
123890 hdpic.t_wiki_zutu Locked - read Low priority read lock
124906 hdpic.t_wiki_zutu Waiting - read Low priority read lock
[/code]
从上述信息可以看出，123890持有的读锁阻塞了2的写入和124906的读操作，这个状态符合我们的推论，接下来处理就比较单纯了，如果现状不可接受，不能继续等待，将123890杀掉，释放资源即可：
再次执行show processlist查看：
已经没有Locked的连接，此时向前端人员询问，告知响应慢的现象也已经消除，服务恢复正常。
原文转自：http://space.itpub.net/7607759/viewspace-696781
虽说简单，但show processlist显示的信息确实是相当有用，有一回，三思收到反馈说MySQL查询很慢，于是，赶紧登录到mysql中，执行show processlist查看当前连接信息：
mysql> show processlist;
+--------+-------------+--------------------+-------+---------+-------+----------------------------------+----------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-------------+--------------------+-------+---------+-------+----------------------------------+----------------------------------------------------------------------------------+
| 1 | system user | | NULL | Connect | 342266| Waiting for master to send event | NULL |
| 2 | system user | | hdpic | Connect | 872 | Locked | UPDATE a SET STATE=0 WHERE ID=83752 |
| 123890 | hdpic_read | 192.168.1.79:54910 | hdpic | Query | 1512 | Sending data | select z.ID,z.TITLE,z.CREATOR_USER_NICK,z.CREATOR_USER_IDEN,z.LASTEDITOR_TI |
| 124906 | hdpic_read | 192.168.1.39:18844 | hdpic | Query | 845 | Locked | select * from a where ((ID = 78789) AND (STATE != 0)) |
| 124912 | hdpic_read | 192.168.1.39:18862 | hdpic | Query | 845 | Locked | select * from a where ((ID = 16031) AND (STATE != 0)) |
| 124914 | hdpic_read | 192.168.1.39:18865 | hdpic | Query | 837 | Locked | select * from a where ((ID = 39109) AND (STATE != 0)) |
| 124917 | hdpic_read | 192.168.1.39:18875 | hdpic | Query | 833 | Locked | select * from a where ((ID = 16031) AND (STATE != 0)) |
一堆的Locked，怪不得慢啊，阻塞的时间不短了，十几分钟。
通常来说存在Locked就说明当前读写操作存在被阻塞的情况，一般我们看到锁都会下意识认为是由于写阻塞了读，上面的结果看仿佛也符合这一特征：只有一条UPDATE，而无数条的SELECT。猜是必须的，但不能瞎猜，这毕竟是线上系统，就算想杀连接的线程，也是要杀掉造成阻塞的那个，不能把所有Locked的全杀了，不然DBA本人很快也要被人杀了，因此具体情况如何还是需要继续分析。
从show processlist查看到的信息来看，UPDATE的语句是很简单的，分析a的表结构，该表为MyISAM表，ID为该表主键，该条更新应该能够瞬间执行完，即使系统繁忙也不应该，而且通过查看当前的系统状态，整体负载很低，iostat中看I/Owait几可忽略，该写操作不太可能这么长时间都没有执行完。
这个时候再分析show processlist中显示的信息，发现id 123890的语句执行时间最长，肯定是在该UPDATE语句之前执行的，通过show full processlist查看语句详表，看到该查询也访问到了a表，经此分析，应该是该语句长时间的读阻塞了写，而被阻塞的写操作由于处于最优先处理队列，又阻塞了其它的读。
不过这些都还只是我们的推论，考虑到线上系统服务的可靠性，最好还是能找到更确切的证据，而后再做操作。
mysqladmin命令有一个debug参数，可以分析当前MySQL服务的状态信息，同时也可以用来帮助我们定位当前锁的详细情况，这里我们通过该命令分析一下当前MySQL服务的详细状态，执行mysqladmin命令如下：
[code="linux"]
# mysqladmin -ujss -p -S /data/3306/mysql.sock debug
Enter password:
[/code]
debug会将状态信息生成到mysql的错误文件，一般锁的信息都会保存在最后几行，这里我们在操作系统层error log最后几行：
[code="linux"]
# tail -10 phpmysql02.err
Thread database.table_name Locked/Waiting Lock_type
2 hdpic.t_wiki_zutu Waiting - write Highest priority write lock
123890 hdpic.t_wiki_zutu_category Locked - read Low priority read lock
123890 hdpic.t_wiki_zutu_photo Locked - read Low priority read lock
123890 hdpic.t_wiki_zutu Locked - read Low priority read lock
124906 hdpic.t_wiki_zutu Waiting - read Low priority read lock
[/code]
从上述信息可以看出，123890持有的读锁阻塞了2的写入和124906的读操作，这个状态符合我们的推论，接下来处理就比较单纯了，如果现状不可接受，不能继续等待，将123890杀掉，释放资源即可：
mysql> kill 123890;
Query OK, 0 rows affected (0.00 sec)
再次执行show processlist查看：
mysql> show processlist;
+--------+-------------+--------------------+-------+---------+--------+----------------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+--------+-------------+--------------------+-------+---------+--------+----------------------------------+------------------+
| 1 | system user | | NULL | Connect | 342390 | Waiting for master to send event | NULL |
| 124906 | hdpic_read | 192.168.1.39:18844 | hdpic | Sleep | 1 | | NULL |
| 124912 | hdpic_read | 192.168.1.39:18862 | hdpic | Sleep | 2 | | NULL |
| 124914 | hdpic_read | 192.168.1.39:18865 | hdpic | Sleep | 1 | | NULL |
| 124917 | hdpic_read | 192.168.1.39:18875 | hdpic | Sleep | 1 | | NULL |
| 124919 | hdpic_read | 192.168.1.39:18877 | hdpic | Sleep | 2 | | NULL |
已经没有Locked的连接，此时向前端人员询问，告知响应慢的现象也已经消除，服务恢复正常。
原文转自：http://space.itpub.net/7607759/viewspace-696781
扫一扫
282
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
