webgame中Mysql Deadlock ERROR 1213 (40001)错误的排查历程

案例发现: 从我们正在运营的一款webgame的异常日志中看到一些程序执行MYSQL 语句的报错信息。比较多的是 “Deadlock found when trying to get lock; try restarting transaction” ,少部分是“Error number: 1205:Lock wait timeout exceeded; try restarti

案例发现:
从我们正在运营的一款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:<i>本文来源gaodai$ma#com搞$代*码网2</i> 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。

喜欢 (0)赏

[搞代码]

分享 (0)