MySQL锁调试实战
本文介绍了一个Hibernate更新操作遇到的MySQL锁超时问题及其解决过程。通过使用MySQL的show full processlist命令和information_schema库中的innodb_trx、innodb_locks、innodb_lock_waits表，定位并解决了由未释放锁导致的阻塞问题。
MySQL锁的调试
今天做Hibernate demo 的时候遇到了锁的问题，现在把这个问题展示出来。
Hibernate更新某个实体：
/**
* org.hibernate.exception.LockTimeoutException: could not execute statement
*/
@Test
public void test895() {
Worker worker = workDao.get(1);
System.out.println(worker.getVersion());
worker.setName(Thread.currentThread().getName());
System.out.println("commit=" + HibernateUtil.getSessionFactory()
.getCurrentSession().hashCode());
HibernateUtil.getSessionFactory().getCurrentSession().getTransaction()
.commit();
System.out.println("commit end");
}Hibernate简单的更新一个实体，报如下错误：
before=209429254
current session hashcode=209429254
Hibernate: select worker0_.id as id1_2_0_, worker0_.age as age2_2_0_, worker0_.name as name3_2_0_, worker0_.version as version4_2_0_ from tb_worker worker0_ where worker0_.id=?
1
commit=209429254
Hibernate: update tb_worker set age=?, name=?, version=? where id=? and version=?
十二月 02, 2014 5:38:02 下午 org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
WARN: SQL Error: 1205, SQLState: 41000
十二月 02, 2014 5:38:02 下午 org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
ERROR: Lock wait timeout exceeded; try restarting transaction
org.hibernate.exception.LockTimeoutException: could not execute statement
at org.hibernate.dialect.MySQLDialect$1.convert(MySQLDialect.java:447)锁超时，那么我们来看一下到底是哪个锁阻塞了当前的更新。
通过show full processlist;可以看到当前的所有的mysql 线程，如下，
mysql> show full processlist;
+----+------+-----------------+--------------------+---------+------+----------+------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------------+--------------------+---------+------+----------+------------------------------------------------------------------------------+
| 45 | root | localhost:51328 | test | Sleep | 1207 | | NULL |
| 46 | root | localhost:51332 | test | Sleep | 1206 | | NULL |
| 61 | root | localhost:51518 | test | Sleep | 4671 | | NULL |
| 62 | root | localhost:51519 | test | Sleep | 4667 | | NULL |
| 63 | root | localhost:51525 | test | Sleep | 4578 | | NULL |
| 64 | root | localhost:51526 | test | Sleep | 4522 | | NULL |
| 67 | root | localhost:51590 | test | Sleep | 4011 | | NULL |
| 68 | root | localhost:51592 | test | Sleep | 3957 | | NULL |
| 69 | root | localhost:51911 | test | Sleep | 3711 | | NULL |
| 70 | root | localhost:51912 | test | Sleep | 3657 | | NULL |
| 71 | root | localhost:52108 | test | Sleep | 3256 | | NULL |
| 72 | root | localhost:52111 | test | Sleep | 3310 | | NULL |
| 73 | root | localhost:52417 | test | Sleep | 2965 | | NULL |
| 74 | root | localhost:52418 | test | Sleep | 2911 | | NULL |
| 75 | root | localhost:52428 | test | Sleep | 2850 | | NULL |
| 76 | root | localhost:52429 | test | Sleep | 2796 | | NULL |
| 77 | root | localhost:52452 | test | Sleep | 2649 | | NULL |
| 78 | root | localhost:52453 | test | Sleep | 2646 | | NULL |
| 79 | root | localhost:52464 | test | Sleep | 2548 | | NULL |
| 80 | root | localhost:52466 | test | Sleep | 2551 | | NULL |
| 84 | root | localhost:53393 | information_schema | Query | 0 | init | show full processlist |
| 89 | root | localhost:53880 | test | Query | 4 | updating | update tb_worker set age=80, name='main', version=2 where id=1 and version=1 |
+----+------+-----------------+--------------------+---------+------+----------+------------------------------------------------------------------------------+其中一个正是我们运行的更新
89 | root | localhost:53880 | test | Query | 4 | updating | update tb_worker set age=80, name='main', version=2 where id=1 and version=1 |那么如何调试这样的错误，通过
information_schema 库的三个关于锁的表（MEMORY引擎）；
innodb_trx ## 当前运行的所有事务
innodb_locks ## 当前出现的锁
innodb_lock_waits ## 锁等待的对应关系
当运行测试中的更新后，进行如下查询：
mysql> select * from innodb_trx order by trx_id desc limit 1 \G
*************************** 1. row ***************************
trx_id: 253697
trx_state: LOCK WAIT
trx_started: 2014-12-02 17:47:57
trx_requested_lock_id: 253697:910:3:2
trx_wait_started: 2014-12-02 17:47:57
trx_weight: 2
trx_mysql_thread_id: 90
trx_query: update tb_worker set age=80, name='main', version=2 where id=1 and version=1
trx_operation_state: starting index read
trx_tables_in_use: 1
trx_tables_locked: 1
trx_lock_structs: 2
trx_lock_memory_bytes: 360
trx_rows_locked: 1
trx_rows_modified: 0
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 10000
trx_is_read_only: 0
trx_autocommit_non_locking: 0
1 row in set (0.00 sec)
mysql> select * from innodb_locks \G
*************************** 1. row ***************************
lock_id: 253697:910:3:2
lock_trx_id: 253697
lock_mode: X
lock_type: RECORD
lock_table: `test`.`tb_worker`
lock_index: PRIMARY
lock_space: 910
lock_page: 3
lock_rec: 2
lock_data: 1
*************************** 2. row ***************************
lock_id: 253640:910:3:2
lock_trx_id: 253640
lock_mode: X
lock_type: RECORD
lock_table: `test`.`tb_worker`
lock_index: PRIMARY
lock_space: 910
lock_page: 3
lock_rec: 2
lock_data: 1
2 rows in set (0.00 sec)
mysql> select * from innodb_lock_waits \G
*************************** 1. row ***************************
requesting_trx_id: 253697
requested_lock_id: 253697:910:3:2
blocking_trx_id: 253640
blocking_lock_id: 253640:910:3:2
1 row in set (0.00 sec)
mysql>分析一下查询结果，
trx_id: 253697这个事务正是我们运行的更新事务，trx_query: update tb_worker set age=80, name='main', version=2 where id=1 and version=1。
在innodb_locks 表中，可以看到有两个锁，分别是lock_id: 253697:910:3:2 和 lock_id: 253640:910:3:2，前一个锁的持有者就是我们的更新事务。后一个锁的持有者是trx_id: 253640，这个事务trx_id: 253640 一直没有释放这个锁，那么这个事务trx_id: 253640是干什么的，来查一下，如下，
mysql> select * from innodb_trx where trx_id = 253640 \G
*************************** 1. row ***************************
trx_id: 253640
trx_state: RUNNING
trx_started: 2014-12-02 16:25:36
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 2
trx_mysql_thread_id: 62
trx_query: NULL
trx_operation_state: NULL
trx_tables_in_use: 0
trx_tables_locked: 0
trx_lock_structs: 2
trx_lock_memory_bytes: 360
trx_rows_locked: 1
trx_rows_modified: 0
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 10000
trx_is_read_only: 0
trx_autocommit_non_locking: 0
1 row in set (0.00 sec)正是这个事务持有锁没有释放。这个事务是干什么的，从表中的信息也没有看出来。
通过innodb_lock_waits 表，我们看到阻塞当前更新事务的blocking_trx_id: 253640，其持有的锁是blocking_lock_id: 253640:910:3:2。
我们现在要做的就是杀死 trx_id: 253640该事务的mysql线程trx_mysql_thread_id: 62。
如何做，如下，
mysql> show full processlist;
+----+------+-----------------+--------------------+---------+------+-------+-----------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+------+-----------------+--------------------+---------+------+-------+-----------------------+
| 45 | root | localhost:51328 | test | Sleep | 2320 | | NULL |
| 46 | root | localhost:51332 | test | Sleep | 2319 | | NULL |
| 61 | root | localhost:51518 | test | Sleep | 5784 | | NULL |
| 62 | root | localhost:51519 | test | Sleep | 5780 | | NULL |
| 63 | root | localhost:51525 | test | Sleep | 5691 | | NULL |
| 64 | root | localhost:51526 | test | Sleep | 5635 | | NULL |
| 67 | root | localhost:51590 | test | Sleep | 5124 | | NULL |
| 68 | root | localhost:51592 | test | Sleep | 5070 | | NULL |
| 69 | root | localhost:51911 | test | Sleep | 4824 | | NULL |
| 70 | root | localhost:51912 | test | Sleep | 4770 | | NULL |
| 71 | root | localhost:52108 | test | Sleep | 4369 | | NULL |
| 72 | root | localhost:52111 | test | Sleep | 4423 | | NULL |
| 73 | root | localhost:52417 | test | Sleep | 4078 | | NULL |
| 74 | root | localhost:52418 | test | Sleep | 4024 | | NULL |
| 75 | root | localhost:52428 | test | Sleep | 3963 | | NULL |
| 76 | root | localhost:52429 | test | Sleep | 3909 | | NULL |
| 77 | root | localhost:52452 | test | Sleep | 3762 | | NULL |
| 78 | root | localhost:52453 | test | Sleep | 3759 | | NULL |
| 79 | root | localhost:52464 | test | Sleep | 3661 | | NULL |
| 80 | root | localhost:52466 | test | Sleep | 3664 | | NULL |
| 84 | root | localhost:53393 | information_schema | Query | 0 | init | show full processlist |
+----+------+-----------------+--------------------+---------+------+-------+-----------------------+
21 rows in set (0.00 sec)
mysql>我们刚才说要杀死 trx_mysql_thread_id: 62的线程，看看在这里有没有，如上，可以看到id = 64 process；
就是他了，杀死他，如下，
mysql> kill 64;
Query OK, 0 rows affected (0.06 sec)
mysql>此时，再来运行一下更新事务，结果如下，
before=209429254
current session hashcode=209429254
Hibernate: select worker0_.id as id1_2_0_, worker0_.age as age2_2_0_, worker0_.name as name3_2_0_, worker0_.version as version4_2_0_ from tb_worker worker0_ where worker0_.id=?
1
commit=209429254
Hibernate: update tb_worker set age=?, name=?, version=? where id=? and version=?
十二月 02, 2014 6:06:51 下午 org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
WARN: SQL Error: 1205, SQLState: 41000
十二月 02, 2014 6:06:51 下午 org.hibernate.engine.jdbc.spi.SqlExceptionHelper logExceptions
ERROR: Lock wait timeout exceeded; try restarting transaction
org.hibernate.exception.LockTimeoutException: could not execute statement他妹的，逗我玩呢，通过以上的分析，我又找到了trx_mysql_thread_id: 62的线程阻塞了当前的事务，该线程所在的事务为，如下，
mysql> select * from innodb_trx where trx_id = 253640 \G
*************************** 1. row ***************************
trx_id: 253640
trx_state: RUNNING
trx_started: 2014-12-02 16:25:36
trx_requested_lock_id: NULL
trx_wait_started: NULL
trx_weight: 2
trx_mysql_thread_id: 62
trx_query: NULL
trx_operation_state: NULL
trx_tables_in_use: 0
trx_tables_locked: 0
trx_lock_structs: 2
trx_lock_memory_bytes: 360
trx_rows_locked: 1
trx_rows_modified: 0
trx_concurrency_tickets: 0
trx_isolation_level: REPEATABLE READ
trx_unique_checks: 1
trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
trx_adaptive_hash_latched: 0
trx_adaptive_hash_timeout: 10000
trx_is_read_only: 0
trx_autocommit_non_locking: 0
1 row in set (0.00 sec)还是这个trx_id: 253640事务，看来真正要做的就是结束这个事务（事务没有结束的原因可能是没有commit，或是当发生异常时，事务没有回滚，没有显示的调用rollback）。
在information_schema.processlist 中，如下，
mysql> select * from processlist where id = 62;
+----+------+-----------------+------+---------+------+-------+------+
| ID | USER | HOST | DB | COMMAND | TIME | STATE | INFO |
+----+------+-----------------+------+---------+------+-------+------+
| 62 | root | localhost:51519 | test | Sleep | 6759 | | NULL |
+----+------+-----------------+------+---------+------+-------+------+
1 row in set (0.03 sec)去Google了一番，没有找到一种显示的结束事务的方法，还是把事务的线程杀死，如下，
mysql> kill 62;
Query OK, 0 rows affected (0.00 sec)执行更新，结果如下，
before=209429254
current session hashcode=209429254
Hibernate: select worker0_.id as id1_2_0_, worker0_.age as age2_2_0_, worker0_.name as name3_2_0_, worker0_.version as version4_2_0_ from tb_worker worker0_ where worker0_.id=?
1
commit=209429254
Hibernate: update tb_worker set age=?, name=?, version=? where id=? and version=?
commit end
Process finished with exit code 0终于成功了。
总结：
事务执行完成后一定要commit
发生异常一定要显示的调用rollback回滚（非aop环境）
参考：http://bbs.chinaunix.net/thread-756036-1-1.html
http://blog.youkuaiyun.com/mchdba/article/details/39459347
http://my.oschina.net/jiaoya/blog/92194
========================END========================
扫一扫
2万+
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
