MYSQL死锁诊断方法

本文思路如下：
1、创建一个student表，插入初始数据；
2、制造死锁；
3、查看show engine innodb status发现死锁SQL；
4、查看binlog发现成功事务执行了哪些SQL。


show engine innodb status不会显示一个事务执行了哪些SQL




一、创建一个student表，插入初始数据
mysql> create table student(id int primary key auto_increment,name varchar(20),class int,age int);
Query OK, 0 rows affected (0.24 sec)


mysql> insert into student values(1,'bruce',1,20);
Query OK, 1 row affected (0.03 sec)


mysql> insert into student values(2,'iori',1,21);
Query OK, 1 row affected (0.03 sec)






二、制造死锁
SESSION 1:
mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)


mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)


mysql> update student set age=30 where id=1;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0


mysql> update student set age=31 where id=2;
Query OK, 0 rows affected (11.37 sec)
Rows matched: 1  Changed: 0  Warnings: 0








SESSION 2:
mysql> set autocommit=0;
Query OK, 0 rows affected (0.00 sec)


mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)


mysql> update student set age=31 where id=2;
Query OK, 0 rows affected (0.00 sec)
Rows matched: 1  Changed: 0  Warnings: 0


mysql> update student set age=30 where id=1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction








三、查看show engine innodb status发现死锁SQL
mysql> show engine innodb status\G;


找到LATEST DETECTED DEADLOCK部分


------------------------
LATEST DETECTED DEADLOCK
------------------------
2016-03-01 16:29:05 7f38d3798700
*** (1) TRANSACTION:
TRANSACTION 4617, ACTIVE 89 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 360, 2 row lock(s), undo log entries 1
MySQL thread id 2, OS thread handle 0x7f38d37d9700, query id 46 localhost root updating
update student set age=31 where id=2
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 90 page no 3 n bits 72 index `PRIMARY` of table `test`.`student` trx id 4617 lock_mode X locks rec but not gap waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80000002; asc     ;;
 1: len 6; hex 00000000120c; asc       ;;
 2: len 7; hex 0b0000013d1335; asc     = 5;;
 3: len 4; hex 696f7269; asc iori;;
 4: len 4; hex 80000001; asc     ;;
 5: len 4; hex 8000001f; asc     ;;


*** (2) TRANSACTION:
TRANSACTION 4620, ACTIVE 41 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 360, 2 row lock(s), undo log entries 1
MySQL thread id 3, OS thread handle 0x7f38d3798700, query id 47 localhost root updating
update student set age=30 where id=1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 90 page no 3 n bits 72 index `PRIMARY` of table `test`.`student` trx id 4620 lock_mode X locks rec but not gap
Record lock, heap no 3 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80000002; asc     ;;
 1: len 6; hex 00000000120c; asc       ;;
 2: len 7; hex 0b0000013d1335; asc     = 5;;
 3: len 4; hex 696f7269; asc iori;;
 4: len 4; hex 80000001; asc     ;;
 5: len 4; hex 8000001f; asc     ;;


*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 90 page no 3 n bits 72 index `PRIMARY` of table `test`.`student` trx id 4620 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 000000001209; asc       ;;
 2: len 7; hex 09000001490343; asc     I C;;
 3: len 5; hex 6272756365; asc bruce;;
 4: len 4; hex 80000001; asc     ;;
 5: len 4; hex 8000001e; asc     ;;


*** WE ROLL BACK TRANSACTION (2)














四、查看binlog发现成功事务执行了哪些SQL
可以根据上一步发现死锁的时间查看binlog
mysqlbinlog -uroot -p  mysql-bin.000007 > mysql-bin.sql


然后找到对应SQL所在事务，查看事务执行了哪些SQL




[root@yw32 mysql]# more mysql-bin.sql |more
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
#160301 16:48:19 server id 1  end_log_pos 120 CRC32 0xe4916f02 Start: binlog v 4, server v 5.6.24-log created 160301 16:48:19
# Warning: this binlog is either in use or was not closed properly.
BINLOG '
U1fVVg8BAAAAdAAAAHgAAAABAAQANS42LjI0LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAQJv
keQ=
'/*!*/;
# at 120
#160301 16:48:36 server id 1  end_log_pos 199 CRC32 0x01a96245 Query thread_id=2 exec_time=0 error_code=0
SET TIMESTAMP=1456822116/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
BEGIN
/*!*/;
# at 199
#160301 16:48:36 server id 1  end_log_pos 309 CRC32 0x45108bf2 Query thread_id=2 exec_time=0 error_code=0
use `test`/*!*/;
SET TIMESTAMP=1456822116/*!*/;
update student set age=30 where id=1
/*!*/;
# at 309
#160301 16:48:45 server id 1  end_log_pos 419 CRC32 0xd79e448e Query thread_id=2 exec_time=6 error_code=0
SET TIMESTAMP=1456822125/*!*/;
update student set age=31 where id=2
/*!*/;
# at 419
#160301 16:49:27 server id 1  end_log_pos 450 CRC32 0xc33b9698 Xid = 157
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;














参照blog：http://www.cnblogs.com/jackluo/p/3336585.html
Mysql Binlog日志分析


通过MysqlBinlog指令查看具体的mysql日志，如下:


///


SET TIMESTAMP=1350355892/*!*/;


BEGIN


/*!*/;


# at 1643330


#121016 10:51:32 server id 1  end_log_pos 1643885        Query     thread_id=272571   exec_time=0   error_code=0


SET TIMESTAMP=1350355892/*!*/;


Insert into T_test….)


/*!*/;


# at 1643885


#121016 10:51:32 server id 1  end_log_pos 1643912        Xid = 0


COMMIT/*!*/;


///


1.开始事物的时间:


SET TIMESTAMP=1350355892/*!*/;


BEGIN


2.sqlevent起点


#at 1643330 :为事件的起点，是以1643330字节开始。


3.sqlevent 发生的时间点


#121016 10:51:32:是事件发生的时间，


4.serverId


server id 1 :为master 的serverId


5.sqlevent终点及花费时间，错误码


end_log_pos 1643885:为事件的终点，是以1643885 字节结束。


execTime 0: 花费的时间


error_code=0:错误码


Xid:事件指示提交的XA事务