案例发现: 从我们正在运营的一款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)错误的排查历程, 感谢原作者分享。

MySQL數據庫升級的步驟包括:1.備份數據庫,2.停止當前MySQL服務,3.安裝新版本MySQL,4.啟動新版本MySQL服務,5.恢復數據庫。升級過程需注意兼容性問題,並可使用高級工具如PerconaToolkit進行測試和優化。

MySQL備份策略包括邏輯備份、物理備份、增量備份、基於復制的備份和雲備份。 1.邏輯備份使用mysqldump導出數據庫結構和數據,適合小型數據庫和版本遷移。 2.物理備份通過複製數據文件,速度快且全面,但需數據庫一致性。 3.增量備份利用二進制日誌記錄變化,適用於大型數據庫。 4.基於復制的備份通過從服務器備份,減少對生產系統的影響。 5.雲備份如AmazonRDS提供自動化解決方案,但成本和控制需考慮。選擇策略時應考慮數據庫大小、停機容忍度、恢復時間和恢復點目標。

MySQLclusteringenhancesdatabaserobustnessandscalabilitybydistributingdataacrossmultiplenodes.ItusestheNDBenginefordatareplicationandfaulttolerance,ensuringhighavailability.Setupinvolvesconfiguringmanagement,data,andSQLnodes,withcarefulmonitoringandpe

在MySQL中優化數據庫模式設計可通過以下步驟提升性能:1.索引優化:在常用查詢列上創建索引,平衡查詢和插入更新的開銷。 2.表結構優化:通過規範化或反規範化減少數據冗餘,提高訪問效率。 3.數據類型選擇:使用合適的數據類型,如INT替代VARCHAR,減少存儲空間。 4.分區和分錶:對於大數據量,使用分區和分錶分散數據,提升查詢和維護效率。

tooptimizemysqlperformance,lofterTheSeSteps:1)inasemproperIndexingTospeedUpqueries,2)使用ExplaintplaintoAnalyzeandoptimizequeryPerformance,3)ActiveServerConfigurationStersLikeTlikeTlikeTlikeIkeLikeIkeIkeLikeIkeLikeIkeLikeIkeLikeNodb_buffer_pool_sizizeandmax_connections,4)

MySQL函數可用於數據處理和計算。 1.基本用法包括字符串處理、日期計算和數學運算。 2.高級用法涉及結合多個函數實現複雜操作。 3.性能優化需避免在WHERE子句中使用函數,並使用GROUPBY和臨時表。

MySQL批量插入数据的高效方法包括:1.使用INSERTINTO...VALUES语法,2.利用LOADDATAINFILE命令,3.使用事务处理,4.调整批量大小,5.禁用索引,6.使用INSERTIGNORE或INSERT...ONDUPLICATEKEYUPDATE,这些方法能显著提升数据库操作效率。

在MySQL中,添加字段使用ALTERTABLEtable_nameADDCOLUMNnew_columnVARCHAR(255)AFTERexisting_column,刪除字段使用ALTERTABLEtable_nameDROPCOLUMNcolumn_to_drop。添加字段時,需指定位置以優化查詢性能和數據結構;刪除字段前需確認操作不可逆;使用在線DDL、備份數據、測試環境和低負載時間段修改表結構是性能優化和最佳實踐。


熱AI工具

Undresser.AI Undress
人工智慧驅動的應用程序,用於創建逼真的裸體照片

AI Clothes Remover
用於從照片中去除衣服的線上人工智慧工具。

Undress AI Tool
免費脫衣圖片

Clothoff.io
AI脫衣器

Video Face Swap
使用我們完全免費的人工智慧換臉工具,輕鬆在任何影片中換臉!

熱門文章

熱工具

ZendStudio 13.5.1 Mac
強大的PHP整合開發環境

mPDF
mPDF是一個PHP庫,可以從UTF-8編碼的HTML產生PDF檔案。原作者Ian Back編寫mPDF以從他的網站上「即時」輸出PDF文件,並處理不同的語言。與原始腳本如HTML2FPDF相比,它的速度較慢,並且在使用Unicode字體時產生的檔案較大,但支援CSS樣式等,並進行了大量增強。支援幾乎所有語言,包括RTL(阿拉伯語和希伯來語)和CJK(中日韓)。支援嵌套的區塊級元素(如P、DIV),

SecLists
SecLists是最終安全測試人員的伙伴。它是一個包含各種類型清單的集合,這些清單在安全評估過程中經常使用,而且都在一個地方。 SecLists透過方便地提供安全測試人員可能需要的所有列表,幫助提高安全測試的效率和生產力。清單類型包括使用者名稱、密碼、URL、模糊測試有效載荷、敏感資料模式、Web shell等等。測試人員只需將此儲存庫拉到新的測試機上,他就可以存取所需的每種類型的清單。

SAP NetWeaver Server Adapter for Eclipse
將Eclipse與SAP NetWeaver應用伺服器整合。

MinGW - Minimalist GNU for Windows
這個專案正在遷移到osdn.net/projects/mingw的過程中,你可以繼續在那裡關注我們。 MinGW:GNU編譯器集合(GCC)的本機Windows移植版本,可自由分發的導入函式庫和用於建置本機Windows應用程式的頭檔;包括對MSVC執行時間的擴展,以支援C99功能。 MinGW的所有軟體都可以在64位元Windows平台上運作。