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--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 log entries 1
MySQL thread id 122562823, OS thread handle 0x7fa5c4fbe700, query id 7457663621 10.1.1.8 s001_gamedb Updating
UPDATE `role_state` SET `state` = 1
WHERE `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 waiting
Record 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 500
mysql tables in use 1, locked 1
6 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 2
MySQL thread id 122679850, OS thread handle 0x7fac007ff700, query id 7457663711 10.1.1.8 s001_gamedb update
REPLACE 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 gap
Record 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 waiting
Record 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 Query thread_id=122679850 exec_time=0 error_code=0
SET TIMESTAMP=1354089586/*!*/;
BEGIN
/*!*/;
# at 511750843
#121128 15:59:46 server id 1 end_log_pos 511751090 Query thread_id=122679850 exec_time=0 error_code=0
use xxx_roles_xxx/*!*/;
SET TIMESTAMP=1354089586/*!*/;
UPDATE `role_pet` SET `in_supporting` = 0, `levelup_pause_time` = 1354089587, `auto_feed` = 0, `supporting_pause_time` = 1354089587
WHERE `role_id` = '53016'
AND `id` = 9234
/*!*/;
# at 511751090
#121128 15:59:46 server id 1 end_log_pos 511751240 Query thread_id=122679850 exec_time=0 error_code=0
SET TIMESTAMP=1354089586/*!*/;
UPDATE `role_state` SET `pet` = 0, `pet_level` = 0
WHERE `role_id` = '53016'
/*!*/;
# at 511751240
#121128 15:59:46 server id 1 end_log_pos 511751885 Query thread_id=122679850 exec_time=0 error_code=0
SET 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 = 7457663579
COMMIT/*!*/;
OK,事务2的SQL语句全部找齐了。那么事务1的呢？如何找？
根据php的异常报错，确定主要包含的语句SQL信息，以及程序跟踪的代码行数，根据代码逻辑去确定该事务的所有SQL语句。再去BINLOG中找到该用户的该业务的类似BINLOG：
# at 511805324 #121128 15:59:53 server id 1 end_log_pos 511805403 Query thread_id=122562823 exec_time=0 error_code=0 SET TIMESTAMP=1354089593/*!*/; BEGIN /*!*/; # at 511805403 #121128 15:59:53 server id 1 end_log_pos 511805560 Query thread_id=122562823 exec_time=0 error_code=0 use 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 Query thread_id=122562823 exec_time=0 error_code=0 SET TIMESTAMP=1354089593/*!*/; UPDATE `role_state` SET `state` = 1 WHERE `role_id` = '53016' /*!*/; # at 511805695 #121128 15:59:53 server id 1 end_log_pos 511805889 Query thread_id=122562823 exec_time=0 error_code=0 use 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 = 7457670215 COMMIT/*!*/;
(请勿过于纠结上面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 | 备注 |
| 1 | begin | ||
| 2 | begin | ||
| 3 | UPDATE `role_state` SET `pet` = 0, `pet_level` = 0 WHERE `role_id` = ’53016′ | 事务2 给 role_state表 role_id 53016记录上 X 锁 | |
| 4 | UPDATE `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)上锁了，开始等待他人提交事务…等待… | |
| 6 | UPDATE `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 | commit | PHP程序发现上一条指令执行完毕，且执行无错，即，发送commit指令，提交事务。 |
好像有个参数%^:
innodb_lock_wait_timeout参数是干啥的呢？从mysql官方手册上看，此参数是针对锁等待时，一个限定等待时间的参数。跟死锁并无关系，一旦mysql发现死锁，立刻回滚导致死锁的语句。并不会用到该参数。
规避方式：
- 缩小事务的语句数量
- 调整SQL语句执行顺序，变“死锁”为“锁等待”，等待一会，总比整个事务回滚掉，全部重新再执行这个流程要强.
- 其他.请补充
关于锁等待:
缩小事务间SQL语句的数量，减小规模吧。当然，提高检索速度，提高查询时间也是首要因素，我们就发现我们的SQL语句中，有几个没有用到索引，导致锁表，导致锁等待发生…
备注:
年底了，冲KPI的，各位见笑了.
原文地址：webgame中Mysql Deadlock ERROR 1213 (40001)错误的排查历程, 感谢原作者分享。
ホットAIツール
Undresser.AI Undress
リアルなヌード写真を作成する AI 搭載アプリ
AI Clothes Remover
写真から衣服を削除するオンライン AI ツール。
Undress AI Tool
脱衣画像を無料で
Clothoff.io
AI衣類リムーバー
AI Hentai Generator
AIヘンタイを無料で生成します。
人気の記事
ホットツール
メモ帳++7.3.1
使いやすく無料のコードエディター
SublimeText3 中国語版
中国語版、とても使いやすい
ゼンドスタジオ 13.0.1
強力な PHP 統合開発環境
ドリームウィーバー CS6
ビジュアル Web 開発ツール
SublimeText3 Mac版
神レベルのコード編集ソフト（SublimeText3）
ホットトピック
7465
15
1376
52
77
11
18
19
MySQLユーザーとデータベースの関係
Apr 08, 2025 pm 07:15 PM
MySQLデータベースでは、ユーザーとデータベースの関係は、アクセス許可と表によって定義されます。ユーザーには、データベースにアクセスするためのユーザー名とパスワードがあります。許可は助成金コマンドを通じて付与され、テーブルはCreate Tableコマンドによって作成されます。ユーザーとデータベースの関係を確立するには、データベースを作成し、ユーザーを作成してから許可を付与する必要があります。
RDS MySQL Redshift Zero ETLとの統合
Apr 08, 2025 pm 07:06 PM
データ統合の簡素化：AmazonrdsmysqlとRedshiftのゼロETL統合効率的なデータ統合は、データ駆動型組織の中心にあります。従来のETL（抽出、変換、負荷）プロセスは、特にデータベース（AmazonrdsmysQlなど）をデータウェアハウス（Redshiftなど）と統合する場合、複雑で時間がかかります。ただし、AWSは、この状況を完全に変えたゼロETL統合ソリューションを提供し、RDSMYSQLからRedshiftへのデータ移行のための簡略化されたほぼリアルタイムソリューションを提供します。この記事では、RDSMysQl Zero ETLのRedshiftとの統合に飛び込み、それがどのように機能するか、それがデータエンジニアと開発者にもたらす利点を説明します。
MySQL：初心者向けのデータ管理の容易さ
Apr 09, 2025 am 12:07 AM
MySQLは、インストールが簡単で、強力で管理しやすいため、初心者に適しています。 1.さまざまなオペレーティングシステムに適した、単純なインストールと構成。 2。データベースとテーブルの作成、挿入、クエリ、更新、削除などの基本操作をサポートします。 3.参加オペレーションやサブクエリなどの高度な機能を提供します。 4.インデックス、クエリの最適化、テーブルパーティション化により、パフォーマンスを改善できます。 5。データのセキュリティと一貫性を確保するために、バックアップ、リカバリ、セキュリティ対策をサポートします。
MySQLのユーザー名とパスワードを入力する方法
Apr 08, 2025 pm 07:09 PM
MySQLのユーザー名とパスワードを入力するには：1。ユーザー名とパスワードを決定します。 2。データベースに接続します。 3.ユーザー名とパスワードを使用して、クエリとコマンドを実行します。
MySQLのクエリ最適化は、特に大規模なデータセットを扱う場合、データベースのパフォーマンスを改善するために不可欠です
Apr 08, 2025 pm 07:12 PM
1.正しいインデックスを使用して、データの量を削減してデータ検索をスピードアップしました。テーブルの列を複数回検索する場合は、その列のインデックスを作成します。あなたまたはあなたのアプリが基準に従って複数の列からのデータが必要な場合、複合インデックス2を作成します2。選択した列のみを避けます。必要な列のすべてを選択すると、より多くのサーバーメモリを使用する場合にのみサーバーが遅くなり、たとえばテーブルにはcreated_atやupdated_atやupdated_atなどの列が含まれます。
NAVICATでデータベースパスワードを取得できますか？
Apr 08, 2025 pm 09:51 PM
NAVICAT自体はデータベースパスワードを保存せず、暗号化されたパスワードのみを取得できます。解決策：1。パスワードマネージャーを確認します。 2。NAVICATの「パスワードを記憶する」機能を確認します。 3.データベースパスワードをリセットします。 4.データベース管理者に連絡してください。
酸性特性を理解する：信頼できるデータベースの柱
Apr 08, 2025 pm 06:33 PM
データベース酸属性の詳細な説明酸属性は、データベーストランザクションの信頼性と一貫性を確保するための一連のルールです。データベースシステムがトランザクションを処理する方法を定義し、システムのクラッシュ、停電、または複数のユーザーの同時アクセスの場合でも、データの整合性と精度を確保します。酸属性の概要原子性：トランザクションは不可分な単位と見なされます。どの部分も失敗し、トランザクション全体がロールバックされ、データベースは変更を保持しません。たとえば、銀行の譲渡が1つのアカウントから控除されているが別のアカウントに増加しない場合、操作全体が取り消されます。 TRANSACTION; updateaccountssetbalance = balance-100wh
mysqlを表示する方法
Apr 08, 2025 pm 07:21 PM
次のコマンドでmysqlデータベースを表示します。サーバーに接続します：mysql -u username -pパスワードrun showデータベース。すべての既存のデータベースを取得するコマンド[データベース]を選択します。データベース名を使用します。テーブルを表示：表を表示します。テーブル構造を表示：テーブル名を説明してください。データを表示：[テーブル名]から[ *]を選択します。
