文档章节

MySQL锁的调试

秋风醉了
 秋风醉了
发布于 2014/12/02 18:28
字数 1755
阅读 338
收藏 0

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.csdn.net/mchdba/article/details/39459347

http://my.oschina.net/jiaoya/blog/92194

========================END========================

© 著作权归作者所有

秋风醉了
粉丝 253
博文 532
码字总数 405557
作品 0
朝阳
程序员
私信 提问
加载中

评论(0)

MySQL MVCC && 事务隔离级别 && 锁

MySQL MVCC && 事务隔离级别 && 锁 InnoDB多版本并发控制——MVCC http://my.oschina.net/xinxingegeya/blog/208821 MySQLS锁X锁read lockwrite lock http://my.oschina.net/xinxingegeya/bl......

秋风醉了
2014/07/30
649
0
Mysql一分钟定位 Next-Key Lock,你需要几分钟

连接与线程 查看连接信息 mysql 非企业版本只支持一个线程一个链接 查看线程模型 【 事务提交策略】 有两个隐藏事务提交时间点需要注意,第一个是 Mysql session 级别的自动提交变量,所有 ...

王清培
01/27
0
0
MySQL · 特性分析 · 到底是谁执行了FTWL

什么是FTWL FTWRL是FLUSH TABLES WITH READ LOCK的简称(FTWRL),该命令主要用于保证备份一致性备份。为了达到这个目的,它需要关闭所有表对象,因此这个命令的杀伤性很大,执行命令时容易导致...

阿里云RDS-数据库内核组
2017/08/05
0
0
MySQL数据库InnoDB存储引擎源代码调试跟踪分析

导读目录: 1 早期结论... 3 2 测试一:死锁检测... 4 3 测试二:cursor测试... 6 4 测试三:external_lock测试... 6 5 测试四:杂项测试... 6 6 测试五:autocommit测试... 7 7 测试六:unl...

吴问志
2011/12/06
315
0
MySQL • 特性分析 • 到底是谁执行了FTWL

摘要: 什么是FTWL FTWRL是FLUSH TABLES WITH READ LOCK的简称(FTWRL),该命令主要用于保证备份一致性备份。为了达到这个目的,它需要关闭所有表对象,因此这个命令的杀伤性很大,执行命令时...

姬子玉
2017/12/13
0
0

没有更多内容

加载失败,请刷新页面

加载更多

Apache Tomcat 8 ARM 移植

tomcat 下载地址 https://tomcat.apache.org/download-80.cgi

osc_y08db3kb
11分钟前
16
0
splunk日志搜索语法笔记

全文搜索 搜索框直接输入”搜索词“   ERROR 查找匹配词”ERROR“ 字段搜索 字段名=”搜索词“ LogLevel=ERROR 查找数据来源为"LogLevel=ERROR" 通配符搜索 Version=5.* 查找数据来源为Ver...

KaWaE
11分钟前
11
0
开发APP、小程序怎么选择云主机的配置

在云服务器的运用上,不仅可以节省高昂的硬件采购成本以及人力成本,后期需要更高配置的云主机时,也可以进行升级,以此减少过高的运维成本,那么开发APP、小程序怎么选择云主机的配置? 内存...

Cloudam云端
12分钟前
13
0
手把手教你开发docker一样的命令行

目录 前言 一、安装 二、初始化应用 初始化项目 创建入口文件cmd/root.go 创建主程序main.go 三、如何自定义命令 创建hello子命令 创建version子命令 四、如何设置flag选项 全局选项 本地选项...

osc_b9r67jnt
13分钟前
12
0
[PHP] 解决mysql下1366 Incorrect string value错误

这个错误是字符编码的问题 , 因为内容里有可能有表情等特殊字符 , 需要使用utf8mb4编码 重点还有一个是 , 在php代码中连接上mysql后一定要执行一下 set name utf8mb4 否则也是不行的 比如下面...

osc_kvlhvh2u
14分钟前
13
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部