Troubleshooting of MysqlDeadlockERROR1213 (40001) errors in webgame

Case study: Some program execution MYSQL statement error messages are displayed in the exception log of A webgame we are operating. "Deadlockfoundwhentryingtogetlock; tryrestartingtransaction" is commonly used, and "Errornumber: 1205: Lockwaittimeoutexceeded; tryrestarti

Case study: Some program execution MYSQL statement error messages are displayed in the exception log of A webgame we are operating. "Deadlock found when trying to get lock; try restarting transaction", and "Error number: 1205: Lock wait timeout exceeded; try restarti

Case study:
The error message about MYSQL statement execution is displayed in the exception log of A webgame that we are operating. Most of them are"Deadlock found when trying to get lock; try restarting transaction", The following is a small part: "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.

From the English perspective of the error message, there are two errors: "deadlock" and "transaction lock wait timeout. What's more, they are all problems with the background PHP resident process. The number of lines corresponding to the Exception Code can be considered as a command for executing SQL statements, and there is nothing special. Experienced programmers can easily see that this is not a program exception. This is an exception in MYSQL transactions, lock competition, and the client (PHP Resident Process) has no syntax errors. How can we troubleshoot this problem?

A string of questions:
What's the problem? How to troubleshoot? When will a deadlock occur? How do I know what happened to him? Where can I troubleshoot the problem? How to troubleshoot? How to determine all SQL statements in their corresponding transactions? Which transactions are there? Who locks first? Who is locked? Who did not lock it? Who reported the deadlock error? What is a deadlock? Why? How to avoid it? What are the other factors?

No clue:
What is the strace artifact for Data Interaction between programs?
Who will be tracked? Client (php )? Do you know which client will have this problem? Do you know when it will happen? What is the amount of data that you need when you start to capture packets to catch deadlocks?
Who will be tracked? Server (Mysql )? Are you kidding me? Mysql processes client requests in process mode. Every time it is a new process, if the strace-ff parameter is used, how many log files have to be created. Will the data volume be small?
I don't have the ability to take the lead among hosts... Check this error with strace.
Who reported the error? Obviously it is mysql, then find the MYSQL server from the root.

Captured site:
We want to restore the crime scene. Fortunately, we have monitoring records BINLOG and show engine innodb status. On the corresponding mysql server, Run "show engine innodb status" to obtain the current information of the INNODB engine, which is roughly as follows:

......------------------------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)......

This is my simplified information. I caught the LATEST DETECTED DEADLOCK part of the data, which is the last DEADLOCK information in INNODB, for more details, see the MYSQL official manual's explanation of the returned results of Standard Monitor and Lock Monitor Output.
OK. I found a case where I saved the INNODB status data for backup. Quickly go to the program exception log to viewSame time pointWhether a deadlock occurs. Sure enough, we recorded this case in the program exception log (the log at the beginning of the article ).
In the binlog, capture the mysql SQL statement execution logs of 10 minutes (about the range) before and after the time period.

Case Analysis:
In engine status, we can see that MYSQL records the data left by the lock contention between two transactions,

Transaction 1 "executed" (note that double quotation marks are added here)

UPDATE `role_state` SET `state` = 1 WHERE `role_id` = '53016'

It is found that the modified resource has been lock_mode X locks (for details, see INNODB Lock mode) and is ready to wait for the resource lock to be released.

Transaction 2 execution

REPLACE INTO `role_fight` (`role_id`, `life_max`, `mana_max`, `attack_physical`, `attack_internal`,****) VALUES ('53016', 4967, 3291, 350, 174, ***)

It is also found that the resource is lock_mode X locks.

In the last part, mysql gave a very important piece of data "we roll back transaction (1)". MYSQL rolled back transaction 1. Since mysql rolls back 1, it must have triggered a deadlock in the statement of transaction 1, which was rolled back by mysql, that is, the part that should be recorded in the exception log in the program. At the same time, MYSQL executes transaction 2, so the SQL statement of transaction 2 must be recorded in the BINLOG.

Loose:
How to determine which SQL statements are executed in transaction 1 and transaction 2?
Based on the results of show engine innodb status, determine whether transaction 2 is executed

• SQL statement (the unique identifier of the role_id of the business logic): REPLACE INTO 'Role _ fight '('Role _ id', 'life _ max', 'mana _ max ', 'attack _ physical ', 'attack _ internal', ***) VALUES ('000000', 53016 1, 4967,329 ,***)
• Thread ID (Unique id of mysql): MySQL thread ID 122679850
• Execution time (timeline): 121128 15:59:46

Based on the three identifiers and the start of the BINLOG, "BEGIN, COMMIT" can be used to determine almost 100% of the SQL statements contained in the firm.

The BINLOG information is roughly as follows:

# 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. All SQL statements of transaction 2 are available. What about transaction 1? How to find it?

Based on the php exception reporting error, determine the SQL statement information mainly contained, and the number of code lines tracked by the program, and determine all SQL statements of the transaction according to the code logic. Go to BINLOG to findThis userOfThis serviceSimilar to 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/*!*/;

(Do not worry too much about the consistency between the thread_id of binlog and the thread_id of show engine innodb status. This is because our program is a resident process and mysql connection is continuously opened and not destroyed, so it is consistent. In addition, this log is a transaction that is committed again after mysql rolls back after the program finds a deadlock. It is the same transaction at different time points)

Case reproduction:
Based on the full SQL statements of the two MYSQL INNODB transactions at the scene of the incident, and the reasons for the MYSQL INNODB deadlock (thanks to the DBA team for correction), we can restore the case like this:

Transaction 1:
UPDATE 'Role _ fight 'SET 'last _ update_life' = '000000' WHERE 'Role _ id' = '000000 ′
UPDATE 'Role _ state' SET 'state' = 1 WHERE 'Role _ id' = '000000 ′

Transaction 2:
UPDATE 'Role _ state' SET 'Pet '= 0, 'Pet _ level' = 0 WHERE 'Role _ id' = '200 ′
Replace into 'Role _ fight '('Role _ id', 'life _ max', 'mana _ max ', 'attack _ physical', 'attack _ internal ', * ***) VALUES ('000000', 53016 1, 4967,329 ,***)

These four statements constitute the full cause of the deadlock in this transaction.
The execution sequence must be as follows:

Time Point	Transaction 1	Transaction 2	Remarks
1	Begin
2	Begin
3	UPDATE 'Role _ state' SET 'Pet '= 0, 'Pet _ level' = 0 WHERE 'Role _ id' = '200 ′	Transaction 2 locks X to the role_state table role_id 53016 record
4	UPDATE 'Role _ fight 'SET 'last _ update_life' = '000000' WHERE 'Role _ id' = '000000 ′	Transaction 1 locks X to the role_fight table role_id 53016 record
5	Replace into 'Role _ fight '('Role _ id', 'life _ max', 'mana _ max ', 'attack _ physical', 'attack _ internal ', * ***) VALUES ('000000', 53016 1, 4967,329 ,***)	Here is the focus. Transaction 2 locks X on the record of role_id in the role_fight table, and finds that it is locked by another person (transaction 1) and starts waiting for another person to submit the transaction... Wait...
6	UPDATE 'Role _ state' SET 'state' = 1 WHERE 'Role _ id' = '000000 ′	Transaction 1 intends to apply the X exclusive lock to the role_state table role_id as the 53016 record. It is found that the transaction has been committed by another transaction and the transaction is still waiting for it to be committed. At this time, MYSQL immediately rolls back transaction 1... (When php finds that MYSQL returns the deadlock information, it records the information to the exception log... Send rollback command... Mysql has been rolled back for help ...)
7	[Execution successful ...]	Transaction 2 finds that someone else has released the lock, OK, get the X lock, modification successful
8	Commit	The PHP program finds that the execution of the previous command is complete and there is no error. That is, it sends the commit command and submits the transaction.

It seems that there is a parameter % ^ &#:
What is the innodb_lock_wait_timeout parameter? From the mysql official manual, this parameter is a parameter that limits the wait time for a lock wait. It has nothing to do with deadlocks. Once mysql finds a deadlock, it immediately rolls back the statement that causes the deadlock. This parameter is not used.

Avoidance Method:

• Reduce the number of statements in a transaction
• Adjust the SQL statement execution sequence and change "deadlock" to "lock wait". Wait for a while, which is better than rolling back the entire transaction.
• Others. Please add

Lock wait:
Reduce the number of SQL statements between transactions. Of course, increasing the search speed and query time are also the primary factors. We found that some of our SQL statements do not use indexes, resulting in Table locking and lock wait...

Note:
At the end of the year, everyone laughed at the KPI.

Original article address: The Troubleshooting process of Mysql Deadlock ERROR 1213 (40001) in webgame. Thank you for sharing with me.