从我们正在运营的一款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--Debug
002 --> 2012-11-22 06:05:36 --> ERROR -->system/database/Driver.php--295--error--JV_Driver
003 --> 2012-11-22 06:05:36 --> ERROR -->system/database/ActiveRecord.php--947--query--JV_Driver
004 --> 2012-11-22 06:05:36 --> ERROR -->server/models/MRoleMonster.php--84--update--JV_ActiveRecord
005 --> 2012-11-22 06:05:36 --> ERROR -->server/daemon/update.php--392--kill--MRoleMonster
006 --> 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:dbwRole
001 --> 2012-11-28 15:59:47 --> ERROR -->system/database/Driver.php--777--log--Debug
002 --> 2012-11-28 15:59:47 --> ERROR -->system/database/Driver.php--295--error--JV_Driver
003 --> 2012-11-28 15:59:47 --> ERROR -->system/database/ActiveRecord.php--948--query--JV_Driver
004 --> 2012-11-28 15:59:47 --> ERROR -->server/models/MRole.php--1143--update--JV_ActiveRecord
005 --> 2012-11-28 15:59:47 --> ERROR -->server/daemon/update_other.php--283--updateRoleState--MRole
006 --> 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` = 1
WHERE `role_id` = '53016'.#####
--> query elapsed counter: 4972;time 4.2417307
--> Database Connection has be closed:dbwRole
007 --> 2012-11-28 15:59:47 --> ERROR -->system/database/Driver.php--616--log--Debug
008 --> 2012-11-28 15:59:47 --> ERROR -->server/daemon/combat_update.php--308--transComplete--JV_Driver
009 --> 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 read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1248, 2 row lock(s), undo