mysql错误码 1213_webgame中Mysql Deadlock ERROR 1213 (40001)错误的排查历程_MySQL

秒速五厘米 2023-01-11 03:56 119阅读 0赞

bitsCN.com

案例发现:

从我们正在运营的一款webgame的异常日志中看到一些程序执行MYSQL 语句的报错信息。比较多的是“Deadlock found when trying to get lock; try restarting transaction”,少部分是“Error number: 1205:Lock wait timeout exceeded; try restarting transaction”，如下：001 --> 2012-11-22 06:05:36 --> ERROR -->system/database/Driver.php--777--log--Debug002 --> 2012-11-22 06:05:36 --> ERROR -->system/database/Driver.php--295--error--JV\_Driver003 --> 2012-11-22 06:05:36 --> ERROR -->system/database/ActiveRecord.php--947--query--JV\_Driver004 --> 2012-11-22 06:05:36 --> ERROR -->server/models/MRoleMonster.php--84--update--JV\_ActiveRecord005 --> 2012-11-22 06:05:36 --> ERROR -->server/daemon/update.php--392--kill--MRoleMonster006 --> 2012-11-22 06:05:36 --> ERROR --> DATABASE: xxx\_roles\_xxx(10.1.1.75) --> Error number: 1205:\#\#\#\#\#Lock wait timeout exceeded; try restarting transaction\#\#\#\#\# --> Error Message: \#\#\#\#\#db\_query\_error --> Query Error: UPDATE \`monster\` SET \`kills\` = kills + 1 WHERE \`id\` = '30036' AND \`role\_id\` = '19863'.\#\#\#\#\# --> query elapsed counter: 184293;time 590.4272678 --> Database Connection has be closed:dbwRole001 --> 2012-11-28 15:59:47 --> ERROR -->system/database/Driver.php--777--log--Debug002 --> 2012-11-28 15:59:47 --> ERROR -->system/database/Driver.php--295--error--JV\_Driver003 --> 2012-11-28 15:59:47 --> ERROR -->system/database/ActiveRecord.php--948--query--JV\_Driver004 --> 2012-11-28 15:59:47 --> ERROR -->server/models/MRole.php--1143--update--JV\_ActiveRecord005 --> 2012-11-28 15:59:47 --> ERROR -->server/daemon/update\_other.php--283--updateRoleState--MRole006 --> 2012-11-28 15:59:47 --> ERROR --> DATABASE: xxx\_roles\_xxx(10.1.1.72) --> Error number: 1213:\#\#\#\#\#Deadlock found when trying to get lock; try restarting transaction\#\#\#\#\# --> Error Message: \#\#\#\#\#db\_query\_error --> Query Error: UPDATE \`role\_state\` SET \`state\` = 1WHERE \`role\_id\` = '53016'.\#\#\#\#\# --> query elapsed counter: 4972;time 4.2417307 --> Database Connection has be closed:dbwRole007 --> 2012-11-28 15:59:47 --> ERROR -->system/database/Driver.php--616--log--Debug008 --> 2012-11-28 15:59:47 --> ERROR -->server/daemon/combat\_update.php--308--transComplete--JV\_Driver009 --> 2012-11-28 15:59:47 --> ERROR --> DB Transaction Failure.

从报错的英文上理解，大约是发生了“死锁”，以及“事务锁等待超时”两个错误异常。而且，都是我们后台PHP常驻进程遇到的问题。异常的代码对应行数上，大约可理解为执行SQL语句的一个指令，并无特殊的东西。有经验的程序员，很容易看出来，这不是程序的异常，这是MYSQL事务中，锁竞争的异常，客户端(PHP常驻进程)是没有语法上的错误的。那该如何排查呢？

一串疑问：

这是什么问题？如何排查？什么时候发生死锁？ 我怎么知道他发生了？ 发生之后去哪里排查？如何排查？怎么确定他们对应的事务中的所有SQL语句？ 分别在哪几个事务中？ 谁先锁的？谁后锁的？谁没锁到？谁报的死锁错误？ 死锁是什么？为什么发生了？ 如何避免？还有哪些因素影响？

毫无头绪:

程序间数据交互，上strace神器?

跟踪谁？ 客户端(php)？你知道哪个客户端会发生这个问题？你知道啥时候会发生？在你开始抓包到抓到死锁的期间，这得是多大的数据量？

跟踪谁？ 服务端(Mysql)？玩笑开大了吧？mysql以进程模式来处理客户端请求，每次都是一个新的进程，strace -ff参数的话，想想日志文件得被创建多少个，数据量会小么？

“万军之中取上将首级”这本事我可没…strace排查这种错误，还是算了吧。

这是谁报的错？显然是mysql，那就从根源找起–MYSQL server。

抓获现场:

我们要还原案发现场，有幸的时，我们有监控记录BINLOG以及SHOW ENGINE INNODB STATUS。到对应mysql服务器上，执行“show engine innodb status”获取INNODB引擎当前信息，大约如下：

......------------------------LATEST DETECTED DEADLOCK------------------------121128 15:59:46\*\*\* (1) TRANSACTION:TRANSACTION AC512256, ACTIVE 0 sec starting index readmysql tables in use 1, locked 1LOCK WAIT 4 lock struct(s), heap size 1248, 2 row lock(s), undo log entries 1MySQL thread id 122562823, OS thread handle 0x7fa5c4fbe700, query id 7457663621 10.1.1.8 s001\_gamedb UpdatingUPDATE \`role\_state\` SET \`state\` = 1WHERE \`role\_id\` = '53016'\*\*\* (1) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 477 page no 1386 n bits 128 index \`PRIMARY\` of table \`xxx\_roles\_xxx\`.\`role\_state\` trx id AC512256 lock\_mode X locks rec but not gap waitingRecord lock, heap no 17 PHYSICAL RECORD: n\_fields 80; compact format; info bits 0 0: len 3; hex 00cf18; asc ;;............\*\*\* (2) TRANSACTION:TRANSACTION AC512250, ACTIVE 0 sec inserting, thread declared inside InnoDB 500mysql tables in use 1, locked 16 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 2MySQL thread id 122679850, OS thread handle 0x7fac007ff700, query id 7457663711 10.1.1.8 s001\_gamedb updateREPLACE INTO \`role\_fight\` (\`role\_id\`, \`life\_max\`, \`mana\_max\`, \`attack\_physical\`, \`attack\_internal\`,\*\*\*\*) VALUES ('53016', 4967, 3291, 350, 174, \*\*\*)\*\*\* (2) HOLDS THE LOCK(S):RECORD LOCKS space id 477 page no 1386 n bits 128 index \`PRIMARY\` of table \`xxx\_roles\_xxx\`.\`role\_state\` trx id AC512250 lock\_mode X locks rec but not gapRecord lock, heap no 17 PHYSICAL RECORD: n\_fields 80; compact format; info bits 0............\*\*\* (2) WAITING FOR THIS LOCK TO BE GRANTED:RECORD LOCKS space id 427 page no 488 n bits 192 index \`PRIMARY\` of table \`xxx\_roles\_xxx\`.\`role\_fight\` trx id AC512250 lock\_mode X locks rec but not gap waitingRecord lock, heap no 64 PHYSICAL RECORD: n\_fields 51; compact format; info bits 0......\*\*\* WE ROLL BACK TRANSACTION (1)......

这是我精简之后的信息，我抓去了LATEST DETECTED DEADLOCK部分的数据，这部分的数据是INNODB的最后一次发生死锁的信息，更详细的说明见MYSQL官方手册对Standard Monitor and Lock Monitor Output返回结果的解释。

OK,发现一场案例，保存这个INNODB的状态数据备用。迅速到程序异常日志中查看相同时间点是否有死锁发生。果然，我们程序异常日志中记录了这起案例(文章开头的日志)。

再到binlog中抓去这个时间段前后10分钟(大约范围)的mysql sql语句执行日志。

案情分析：

engine status中，大约看出MYSQL记录了两个事务之间发生锁竞争时，遗留的数据，

事务1“执行”(注意，这里加了双引号)

UPDATE \`role\_state\` SET \`state\` = 1 WHERE \`role\_id\` = '53016'

发现被修改资源已经被lock\_mode X locks了(详情见:INNODB锁模式)，准备等待该资源锁被释放

事务2执行

REPLACE INTO \`role\_fight\` (\`role\_id\`, \`life\_max\`, \`mana\_max\`, \`attack\_physical\`, \`attack\_internal\`,\*\*\*\*) VALUES ('53016', 4967, 3291, 350, 174, \*\*\*)

也发现该资源被lock\_mode X locks了。

最后部分，mysql给了很重要的一个数据“WE ROLL BACK TRANSACTION (1)” MYSQL回滚了事物1。既然mysql回滚了1，那么肯定是事务1的语句触发了死锁，被mysql回滚了，也就是应该为程序中的异常日志所记录的那部分。同时，MYSQL执行了事务2，那么事务2的SQL语句肯定被记录在BINLOG中了。

抽丝剥茧:

如何确定事务1、事务2执行了哪些SQL语句呢？

根据show engine innodb status的结果，确定事务2被执行的SQL语句(业务逻辑的role\_id唯一标识): REPLACE INTO \`role\_fight\` (\`role\_id\`, \`life\_max\`, \`mana\_max\`, \`attack\_physical\`, \`attack\_internal\`,\*\*\*\*) VALUES (’53016′, 4967, 3291, 350, 174, \*\*\*)

线程ID(mysql的唯一标识): MySQL thread id 122679850

执行时间(时间线):121128 15:59:46

根据这三个标识，以及BINLOG的起始表示“BEGIN、COMMIT”，几乎可以100%确定该事务所包含的SQL语句。

BINLOG信息大约如下:

\# at 511750764\#121128 15:59:46 server id 1 end\_log\_pos 511750843 Querythread\_id=122679850exec\_time=0error\_code=0SET TIMESTAMP=1354089586/\*!\*/;BEGIN/\*!\*/;\# at 511750843\#121128 15:59:46 server id 1 end\_log\_pos 511751090 Querythread\_id=122679850exec\_time=0error\_code=0use xxx\_roles\_xxx/\*!\*/;SET TIMESTAMP=1354089586/\*!\*/;UPDATE \`role\_pet\` SET \`in\_supporting\` = 0, \`levelup\_pause\_time\` = 1354089587, \`auto\_feed\` = 0, \`supporting\_pause\_time\` = 1354089587WHERE \`role\_id\` = '53016'AND \`id\` = 9234/\*!\*/;\# at 511751090\#121128 15:59:46 server id 1 end\_log\_pos 511751240 Querythread\_id=122679850exec\_time=0error\_code=0SET TIMESTAMP=1354089586/\*!\*/;UPDATE \`role\_state\` SET \`pet\` = 0, \`pet\_level\` = 0WHERE \`role\_id\` = '53016'/\*!\*/;\# at 511751240\#121128 15:59:46 server id 1 end\_log\_pos 511751885 Querythread\_id=122679850exec\_time=0error\_code=0SET TIMESTAMP=1354089586/\*!\*/;REPLACE INTO \`role\_fight\` (\`role\_id\`, \`life\_max\`, \`mana\_max\`, \`attack\_physical\`, \`attack\_internal\`, \`defend\_physical\`, \`defend\_internal\`, \`dodge\_rate\`, \`critical\_rate\`, \`hit\_rate\`, \`speed\`, \`defend\_physical\_plus\`, \`defend\_internal\_plus\`, \`dodge\_level\`,\*\*\*\*\*) VALUES ('53016', 4967, 3291, 350, 174, 518, 254, 500, 300, 9500, 913, 668, 668, 261, 700, 97, 133, 40.9, 34, \*\*\*\*\*)/\*!\*/;\# at 511751885\#121128 15:59:46 server id 1 end\_log\_pos 511751912 Xid = 7457663579COMMIT/\*!\*/;

OK,事务2的SQL语句全部找齐了。那么事务1的呢？如何找？

根据php的异常报错，确定主要包含的语句SQL信息，以及程序跟踪的代码行数，根据代码逻辑去确定该事务的所有SQL语句。再去BINLOG中找到该用户的该业务的类似BINLOG：

\# at 511805324\#121128 15:59:53 server id 1 end\_log\_pos 511805403 Querythread\_id=122562823exec\_time=0error\_code=0SET TIMESTAMP=1354089593/\*!\*/;BEGIN/\*!\*/;\# at 511805403\#121128 15:59:53 server id 1 end\_log\_pos 511805560 Querythread\_id=122562823exec\_time=0error\_code=0use xxx\_roles\_xxx/\*!\*/;SET TIMESTAMP=1354089593/\*!\*/;UPDATE \`role\_fight\` SET \`last\_update\_life\` = '1354089587'WHERE \`role\_id\` = '53016'/\*!\*/;\# at 511805560\#121128 15:59:53 server id 1 end\_log\_pos 511805695 Querythread\_id=122562823exec\_time=0error\_code=0SET TIMESTAMP=1354089593/\*!\*/;UPDATE \`role\_state\` SET \`state\` = 1WHERE \`role\_id\` = '53016'/\*!\*/;\# at 511805695\#121128 15:59:53 server id 1 end\_log\_pos 511805889 Querythread\_id=122562823exec\_time=0error\_code=0use xxx\_roles\_xxx/\*!\*/;SET TIMESTAMP=1354089593/\*!\*/;DELETE FROM \`queue\_combats\_update\_roles\`WHERE \`combat\_id\` = 'f27d62dad8efcaeb04cd8f5d7c0424db'AND \`role\_id\` = '53016'/\*!\*/;\# at 511805889\#121128 15:59:53 server id 1 end\_log\_pos 511805916 Xid = 7457670215COMMIT/\*!\*/;

(请勿过于纠结上面binlog的thread\_id跟show engine innodb status的thread\_id一致的问题，这是因为我们程序是常驻进程，mysql连接不断开，不销毁，故一致了。而且，此日志是程序发现死锁之后，被mysql回滚之后，又重新提交的事务，算是不同时间点的相同事务)

案情还原：

根据案发现场的两个MYSQL INNODB事务的全部SQL语句，以及形成MYSQL INNODB 死锁的原因(感谢DBA组大雄哥的纠正)，我们大约可以这么还原案情:

事务1：

UPDATE \`role\_fight\` SET \`last\_update\_life\` = ’1354089587′ WHERE \`role\_id\` = ’53016′

UPDATE \`role\_state\` SET \`state\` = 1 WHERE \`role\_id\` = ’53016′

事务2：

UPDATE \`role\_state\` SET \`pet\` = 0, \`pet\_level\` = 0 WHERE \`role\_id\` = ’53016′

REPLACE INTO \`role\_fight\` (\`role\_id\`, \`life\_max\`, \`mana\_max\`, \`attack\_physical\`, \`attack\_internal\`,\*\*\*\*) VALUES (’53016′, 4967, 3291, 350, 174, \*\*\*)

这四条语句构成了本次事务死锁的全部原因。

执行顺序肯定如下:时间点事务1事务2备注1begin 2 begin 3 UPDATE \`role\_state\` SET \`pet\` = 0, \`pet\_level\` = 0 WHERE \`role\_id\` = ’53016′事务2 给 role\_state表 role\_id 53016记录上 X 锁4UPDATE \`role\_fight\` SET \`last\_update\_life\` = ’1354089587′ WHERE \`role\_id\` = ’53016′ 事务1 给 role\_fight表 role\_id 53016记录上 X 锁5 REPLACE INTO \`role\_fight\` (\`role\_id\`, \`life\_max\`, \`mana\_max\`, \`attack\_physical\`, \`attack\_internal\`,\*\*\*\*) VALUES (’53016′, 4967, 3291, 350, 174, \*\*\*)这里是重点，事务2给role\_fight表role\_id的记录上 X 锁，发现被其他人(事务1)上锁了，开始等待他人提交事务…等待…6UPDATE \`role\_state\` SET \`state\` = 1 WHERE \`role\_id\` = ’53016′ 事物1打算给role\_state表role\_id为53016记录上 X 排它锁，发现被其他事务上了，而且此事务居然还在等他提交，这时MYSQL立刻回滚事务1…(php发现MYSQL返回死锁信息，随记录该信息到异常日志…发送回滚指令…mysql已经“帮”他回滚了…)7 【执行成功…】事务2发现别人释放锁了，OK，获取X锁，修改成功8 commitPHP程序发现上一条指令执行完毕，且执行无错，即，发送commit指令，提交事务。

好像有个参数%^:

innodb\_lock\_wait\_timeout参数是干啥的呢？从mysql官方手册上看，此参数是针对锁等待时，一个限定等待时间的参数。跟死锁并无关系，一旦mysql发现死锁，立刻回滚导致死锁的语句。并不会用到该参数。

规避方式：缩小事务的语句数量

调整SQL语句执行顺序，变“死锁”为“锁等待”，等待一会，总比整个事务回滚掉，全部重新再执行这个流程要强.

其他.请补充

关于锁等待:

缩小事务间SQL语句的数量，减小规模吧。当然，提高检索速度，提高查询时间也是首要因素，我们就发现我们的SQL语句中，有几个没有用到索引，导致锁表，导致锁等待发生…

备注:

年底了，冲KPI的，各位见笑了

bitsCN.com

![f68f2add0b68e4f9810432fce46917b7.png][]

本文原创发布php中文网，转载请注明出处，感谢您的尊重！