How to diagnose a MySQL deadlock

-

In this article I will show case a deadlock example encountered in a API call in our application.

NOTE: The blog I referred is:

How to deal with MySQL deadlocks

A deadlock in MySQL happens when two or more transactions mutually hold and request for locks, creating a cycle of dependencies. In a transaction system, deadlocks are a fact of life and not completely avoidable. InnoDB automatically detects transaction deadlocks, rollbacks a transaction immediately and returns an error. It uses a metric to pick the easiest transaction to rollback. Though an occasional deadlock is not something to worry about, frequent occurrences call for attention.

Before MySQL 5.6, only the latest deadlock can be reviewed using SHOW ENGINE INNODB STATUS command. But with Percona Toolkit’s pt-deadlock-logger you can have deadlock information retrieved from SHOW ENGINE INNODB STATUS at a given interval and saved to a file or table for later diagnosis. For more information on using pt-deadlock-logger, see this post. With MySQL 5.6, you can enable a new variable innodb_print_all_deadlocks to have all deadlocks in InnoDB recorded in mysqld error log.

Before and above all diagnosis, it is always an important practice to have the applications catch deadlock error (MySQL error no. 1213) and handles it by retrying the transaction.

A MySQL deadlock could involve more than two transactions, but the LATEST DETECTED DEADLOCK section only shows the last two transactions. Also, it only shows the last statement executed in the two transactions and locks from the two transactions that created the cycle. What is missed are the earlier statements that might have really acquired the locks. I will show some tips on how to collect the missed statements.

Deadlock Output

------------------------
LATEST DETECTED DEADLOCK
------------------------

2021-03-29 13:21:30 0x7fa97dbcb700
*** (1) TRANSACTION:
TRANSACTION 485480058, ACTIVE 1966 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 14 lock struct(s), heap size 1136, 6 row lock(s), undo log entries 6
MySQL thread id 1193881, OS thread handle 140365960050432, query id 3933018996 10.41.10.130 fra01hestage updating
update T_ENT_ACTIVATION set ActivatedBy='swlservice', ActivateeId=null, Aid_id=785349, ActivationDateTime='2021-03-29 11:19:38.0', StartDate='2021-03-29 11:19:38.0', ActivationState=3, EndDate=null, ActivationType=0, ActivatorId=null, AId='a1cb41e5-c2bc-499d-a637-cebb2bd7e18c', createDate='2021-03-29 11:19:38.0', createdBy='swlservice', CSTMRId=null, CSTMRIdentifier=null, DeviceID=null, EID='80c3e5f5-3fec-43ee-8718-16b21c44f222', ENFId=1, ENTId=514129, LineItemId=1219597, ExternalId=null, FamilyId=48, FPFRIENDLYNAME=null, FingerprintId=null, groupActivationId=0, groupGlobalId=null, isTestEnt=0, DurationType=0, loginType=0, modifiedBy='zosfoer1', modifiedDate='2021-03-29 13:21:30.486', NOTIFICATIONALLOWED=0, PreviousActivationId=null, PRDID=8475, PKId='df9a65bf-2954-4139-bbd9-a7c0f4a8eb7f', ProductKeyId=1219597, quantity=1, renewLicense=0, StateChangeDateTime='2021-03-29 11:19:38.0', StateChangedB
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 577 page no 44260 n bits 120 index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` trx id 485480058 lock_mode X locks rec but not gap waiting
Record lock, heap no 12 PHYSICAL RECORD: n_fields 48; compact format; info bits 0
 0: len 4; hex 800bfbc5; asc     ;;
 1: len 6; hex 00001ced44bf; asc     D ;;
 2: len 7; hex 29000034f80e02; asc )  4   ;;
 3: len 4; hex 80129c0d; asc     ;;
 4: SQL NULL;
 5: len 10; hex 73776c73657276696365; asc swlservice;;
 6: len 5; hex 99a93ab4e6; asc   :  ;;
 7: len 4; hex 80000003; asc     ;;
 8: SQL NULL;
 9: SQL NULL;
 10: len 5; hex 99a93ab4e6; asc   :  ;;
 11: len 30; hex 61316362343165352d633262632d343939642d613633372d636562623262; asc a1cb41e5-c2bc-499d-a637-cebb2b; (total 36 bytes);
 12: len 4; hex 80000000; asc     ;;
 13: len 4; hex 80000000; asc     ;;
 14: len 8; hex 8000000000000001; asc         ;;
 15: len 4; hex 80000000; asc     ;;
 16: len 1; hex 80; asc  ;;
 17: SQL NULL;
 18: SQL NULL;
 19: SQL NULL;
 20: len 4; hex 80129c0d; asc     ;;
 21: len 4; hex 8007d851; asc    Q;;
 22: len 4; hex 8000211b; asc   ! ;;
 23: len 4; hex 80000030; asc    0;;
 24: SQL NULL;
 25: len 4; hex 800bfbc5; asc     ;;
 26: len 30; hex 64663961363562662d323935342d343133392d626264392d613763306634; asc df9a65bf-2954-4139-bbd9-a7c0f4; (total 36 bytes);
 27: len 30; hex 38306333653566352d336665632d343365652d383731382d313662323163; asc 80c3e5f5-3fec-43ee-8718-16b21c; (total 36 bytes);
 28: len 1; hex 00; asc  ;;
 29: len 1; hex 80; asc  ;;
 30: len 10; hex 73776c73657276696365; asc swlservice;;
 31: len 5; hex 99a93ab4e6; asc   :  ;;
 32: len 8; hex 7a6f73666f657231; asc zosfoer1;;
 33: len 5; hex 99a93acea6; asc   :  ;;
 34: SQL NULL;
 35: len 4; hex 80000001; asc     ;;
 36: SQL NULL;
 37: len 30; hex 30633031366564622d613163642d346537382d613532362d313164343664; asc 0c016edb-a1cd-4e78-a526-11d46d; (total 36 bytes);
 38: len 3; hex 555443; asc UTC;;
 39: SQL NULL;
 40: SQL NULL;
 41: len 5; hex 99a93ab4e6; asc   :  ;;
 42: SQL NULL;
 43: len 1; hex 80; asc  ;;
 44: SQL NULL;
 45: SQL NULL;
 46: SQL NULL;
 47: len 4; hex 80000001; asc     ;;
 
 *** (2) TRANSACTION:
TRANSACTION 485480060, ACTIVE 1772 sec starting index read
mysql tables in use 1, locked 1
15 lock struct(s), heap size 1136, 7 row lock(s), undo log entries 6
MySQL thread id 1194134, OS thread handle 140365935720192, query id 3933019043 10.41.1.157 fra01hestage updating
update T_ENT_ACTIVATION set ActivatedBy='swlservice', ActivateeId=null, Aid_id=785349, ActivationDateTime='2021-03-29 11:19:38.0', StartDate='2021-03-29 11:19:38.0', ActivationState=3, EndDate=null, ActivationType=0, ActivatorId=null, AId='a1cb41e5-c2bc-499d-a637-cebb2bd7e18c', createDate='2021-03-29 11:19:38.0', createdBy='swlservice', CSTMRId=null, CSTMRIdentifier=null, DeviceID=null, EID='80c3e5f5-3fec-43ee-8718-16b21c44f222', ENFId=1, ENTId=514129, LineItemId=1219597, ExternalId=null, FamilyId=48, FPFRIENDLYNAME=null, FingerprintId=null, groupActivationId=0, groupGlobalId=null, isTestEnt=0, DurationType=0, loginType=0, modifiedBy='zosfoer1', modifiedDate='2021-03-29 13:21:30.504', NOTIFICATIONALLOWED=0, PreviousActivationId=null, PRDID=8475, PKId='df9a65bf-2954-4139-bbd9-a7c0f4a8eb7f', ProductKeyId=1219597, quantity=1, renewLicense=0, StateChangeDateTime='2021-03-29 11:19:38.0', StateChangedBy
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 577 page no 44260 n bits 120 index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` trx id 485480060 lock mode S locks rec but not gap
Record lock, heap no 12 PHYSICAL RECORD: n_fields 48; compact format; info bits 0
 0: len 4; hex 800bfbc5; asc     ;;
 1: len 6; hex 00001ced44bf; asc     D ;;
 2: len 7; hex 29000034f80e02; asc )  4   ;;
 3: len 4; hex 80129c0d; asc     ;;
 4: SQL NULL;
 5: len 10; hex 73776c73657276696365; asc swlservice;;
 6: len 5; hex 99a93ab4e6; asc   :  ;;
 7: len 4; hex 80000003; asc     ;;
 8: SQL NULL;
 9: SQL NULL;
 10: len 5; hex 99a93ab4e6; asc   :  ;;
 11: len 30; hex 61316362343165352d633262632d343939642d613633372d636562623262; asc a1cb41e5-c2bc-499d-a637-cebb2b; (total 36 bytes);
 12: len 4; hex 80000000; asc     ;;
 13: len 4; hex 80000000; asc     ;;
 14: len 8; hex 8000000000000001; asc         ;;
 15: len 4; hex 80000000; asc     ;;
 16: len 1; hex 80; asc  ;;
 17: SQL NULL;
 18: SQL NULL;
 19: SQL NULL;
 20: len 4; hex 80129c0d; asc     ;;
 21: len 4; hex 8007d851; asc    Q;;
 22: len 4; hex 8000211b; asc   ! ;;
 23: len 4; hex 80000030; asc    0;;
 24: SQL NULL;
 25: len 4; hex 800bfbc5; asc     ;;
 26: len 30; hex 64663961363562662d323935342d343133392d626264392d613763306634; asc df9a65bf-2954-4139-bbd9-a7c0f4; (total 36 bytes);
 27: len 30; hex 38306333653566352d336665632d343365652d383731382d313662323163; asc 80c3e5f5-3fec-43ee-8718-16b21c; (total 36 bytes);
 28: len 1; hex 00; asc  ;;
 29: len 1; hex 80; asc  ;;
 30: len 10; hex 73776c73657276696365; asc swlservice;;
 31: len 5; hex 99a93ab4e6; asc   :  ;;
 32: len 8; hex 7a6f73666f657231; asc zosfoer1;;
 33: len 5; hex 99a93acea6; asc   :  ;;
 34: SQL NULL;
 35: len 4; hex 80000001; asc     ;;
 36: SQL NULL;
 37: len 30; hex 30633031366564622d613163642d346537382d613532362d313164343664; asc 0c016edb-a1cd-4e78-a526-11d46d; (total 36 bytes);
 38: len 3; hex 555443; asc UTC;;
 39: SQL NULL;
 40: SQL NULL;
 41: len 5; hex 99a93ab4e6; asc   :  ;;
 42: SQL NULL;
 43: len 1; hex 80; asc  ;;
 44: SQL NULL;
 45: SQL NULL;
 46: SQL NULL;
 47: len 4; hex 80000001; asc     ;;
 *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 577 page no 44260 n bits 120 index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` trx id 485480060 lock_mode X locks rec but not gap waiting
Record lock, heap no 12 PHYSICAL RECORD: n_fields 48; compact format; info bits 0
 0: len 4; hex 800bfbc5; asc     ;;
 1: len 6; hex 00001ced44bf; asc     D ;;
 2: len 7; hex 29000034f80e02; asc )  4   ;;
 3: len 4; hex 80129c0d; asc     ;;
 4: SQL NULL;
 5: len 10; hex 73776c73657276696365; asc swlservice;;
 6: len 5; hex 99a93ab4e6; asc   :  ;;
 7: len 4; hex 80000003; asc     ;;
 8: SQL NULL;
 9: SQL NULL;
 10: len 5; hex 99a93ab4e6; asc   :  ;;
 11: len 30; hex 61316362343165352d633262632d343939642d613633372d636562623262; asc a1cb41e5-c2bc-499d-a637-cebb2b; (total 36 bytes);
 12: len 4; hex 80000000; asc     ;;
 13: len 4; hex 80000000; asc     ;;
 14: len 8; hex 8000000000000001; asc         ;;
 15: len 4; hex 80000000; asc     ;;
 16: len 1; hex 80; asc  ;;
 17: SQL NULL;
 18: SQL NULL;
 19: SQL NULL;
 20: len 4; hex 80129c0d; asc     ;;
 21: len 4; hex 8007d851; asc    Q;;
 22: len 4; hex 8000211b; asc   ! ;;
 23: len 4; hex 80000030; asc    0;;
 24: SQL NULL;
 25: len 4; hex 800bfbc5; asc     ;;
 26: len 30; hex 64663961363562662d323935342d343133392d626264392d613763306634; asc df9a65bf-2954-4139-bbd9-a7c0f4; (total 36 bytes);
 27: len 30; hex 38306333653566352d336665632d343365652d383731382d313662323163; asc 80c3e5f5-3fec-43ee-8718-16b21c; (total 36 bytes);
 28: len 1; hex 00; asc  ;;
 29: len 1; hex 80; asc  ;;
 30: len 10; hex 73776c73657276696365; asc swlservice;;
 31: len 5; hex 99a93ab4e6; asc   :  ;;
 32: len 8; hex 7a6f73666f657231; asc zosfoer1;;
 33: len 5; hex 99a93acea6; asc   :  ;;
 34: SQL NULL;
 35: len 4; hex 80000001; asc     ;;
 36: SQL NULL;
 37: len 30; hex 30633031366564622d613163642d346537382d613532362d313164343664; asc 0c016edb-a1cd-4e78-a526-11d46d; (total 36 bytes);
 38: len 3; hex 555443; asc UTC;;
 39: SQL NULL;
 40: SQL NULL;
 41: len 5; hex 99a93ab4e6; asc   :  ;;
 42: SQL NULL;
 43: len 1; hex 80; asc  ;;
 44: SQL NULL;
 45: SQL NULL;
 46: SQL NULL;
 47: len 4; hex 80000001; asc     ;;
 
 *** WE ROLL BACK TRANSACTION (1)

From the deadlock output we can see that both the transactions are writing and waiting for the same record (AId). It looks like that deadlock is coming because in the same transaction following events are occurring: 

  • Put a Shared Lock (lock mode S) on the record and proceed.
  • Put an exclusive Lock (lock mode X) on the record and proceed.

Hence when 2 transactions Race Condition the sequence of these events, they get trapped in a deadlock. 

*** (1) TRANSACTION:
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 577 page no 44260 n bits 120 index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` trx id 485480058 lock_mode X locks rec but not gap waiting
11: len 30; hex 61316362343165352d633262632d343939642d613633372d636562623262; asc a1cb41e5-c2bc-499d-a637-cebb2b; (total 36 bytes);

*** (2) TRANSACTION:
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 577 page no 44260 n bits 120 index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` trx id 485480060 lock mode S locks rec but not gap
Record lock, heap no 12 PHYSICAL RECORD: n_fields 48; compact format; info bits 0
11: len 30; hex 61316362343165352d633262632d343939642d613633372d636562623262; asc a1cb41e5-c2bc-499d-a637-cebb2b; (total 36 bytes);

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 577 page no 44260 n bits 120 index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` trx id 485480060 lock_mode X locks rec but not gap waiting
11: len 30; hex 61316362343165352d633262632d343939642d613633372d636562623262; asc a1cb41e5-c2bc-499d-a637-cebb2b; (total 36 bytes);

Understanding MySQL Deadlock

Line 1 gives the time when the deadlock happened. If your application code catches and logs deadlock errors, which it should, then you can match this timestamp with the timestamps of deadlock errors in the application log. You would have the transaction that got rolled back. From there, retrieve all statements from that transaction.

Line 3 & 61, take note of Transaction number and ACTIVE time. If you log SHOW ENGINE INNODB STATUS output periodically(which is a good practice), then you can search previous outputs with a transaction number to hopefully see more statements from the same transaction. The ACTIVE sec gives a hint on whether the transaction is a single statement or multi-statement one.

Line 4 & 62, the tables in use and locked are only with respect to the current statement. So having 1 table in use does not necessarily mean that the transaction involves 1 table only.

Line 5 & 63, this is worthy of attention as it tells how many changes the transaction had made, which is the "undo log entries" and how many row locks it held which is "row lock(s)". This info hints the complexity of the transaction.

Line 6 & 64, take note of thread id, connecting host and connecting user. If you use different MySQL users for different application functions which is another good practice, then you can tell which application area the transaction comes from based on the connecting host and user.

Line 9 & 10: The 'space id' is tablespace id, 'page no' gives which page the record lock is on inside the tablespace. The 'n bits' is not the page offset, instead, the number of bits in the lock bitmap. The page offset is the 'heap no' on line 10.

Line 11~15: It shows the record data in hex numbers. Field 0 is the cluster index (primary key). Ignore the highest bit, the value is 785349. Field 1 is the transaction id of the transaction which last modified this record, decimal value is 485311679 which is neither TRANSACTION (1) nor TRANSACTION (2). Hence the record is last modified by some another transaction. Field 2 is the roll-back pointer. Starting from field 3 is the rest of the row data. By reading the data, we know exactly which row is locked and what is the current value.

Line 9, for the first transaction, it only shows the lock it was waiting for. It is waiting for index PRIMARY of table emsent_carlzeissag.t_ent_activation in lock_mode X locks rec but not gap waiting. 

Possible values are S for shared lock and X for exclusive, with or without gap locks.

Line 67, for the second transaction, it shows the lock(s) it holds. It is holding index PRIMARY of table `emsent_carlzeissag`.`t_ent_activation` lock mode S locks rec but not gap.

There are only a few sources for a shared record lock in InnoDB:

  1. use of SELECT … LOCK IN SHARE MODE
  2. on foreign key referenced record(s).
  3. with INSERT INTO… SELECT, shared locks on the source table.
Line 118, for the first transaction, it only shows the lock it was waiting for. It is waiting for index PRIMARY of table emsent_carlzeissag.t_ent_activation in lock_mode X locks rec but not gap waiting.

Line 169, tells you which transaction is rolled back by the system.

You can find the statements in a transaction from various sources like:
  • Binary Log
  • Application Log
  • MySQL General Log
  • MySQL Performance Schema

How to avoid a MySQL Deadlock

There are things that we could do to eliminate a deadlock after we understand it.

  • Make changes to the application. In some cases, you could greatly reduce the frequency of deadlocks by splitting a long transaction into smaller ones, so locks are released sooner. In other cases, the deadlock rises because two transactions touch the same sets of data, either in one or more tables, with different orders. Then change them to access data in the same order, in another word, serialize the access. That way you would have lock wait instead of deadlock when the transactions happen concurrently.
  • Make changes to the table schema, such as removing foreign key constraint to detach two tables, or adding indexes to minimize the rows scanned and locked.
  • In case of gap locking, you may change the transaction isolation level to read committed for the session or transaction to avoid it. But then the binlog format for the session or transaction would have to be ROW or MIXED.

Comments

Post a Comment

Back To Top

Popular posts from this blog

error 18 at 0 depth lookup: self signed certificate

-
I was trying to test SSL connection between MySQL client and server. For that I created SSL certificate and keys by following the MySQL documentation at: Creating SSL Certificates and Keys Using openssl After finishing up all the commands when I verify the certificates by using: openssl verify -CAfile ca.pem server-cert.pem client-cert.pem I got the following output: error 18 at 0 depth lookup : self signed certificate error server-cert.pem: verification failed client-cert.pem: OK  Reason : The Common Name value used for the server and client certificates/keys must each differ from the Common Name value used for the CA certificate. Otherwise, the certificate and key files will not work for servers compiled using OpenSSL. Solution : When OpenSSL prompts you for the Common Name for each certificate, use different names. Common Name (e.g. server FQDN or YOUR name) []: I used values as follows: CA Cert:  ssl-ca-cert Server Cert: ssl-ca-server-cert Client Cer...
Read more

How to check fragmentation in MySQL tables

-
MySQL tables, including MyISAM and InnoDB, two of the most common types, experience fragmentation as data is inserted, updated and deleted randomly. Fragmentation can leave large holes in your table, blocks which must be read when scanning the table. Optimizing your table can therefore make full table scans and range scans more efficient. We will mention how to check fragmentation in MySQL tables using SQL queries. USE < put_your_dbname_here > SELECT TABLE_NAME, CONCAT(ROUND(( data_length + index_length ) / ( 1024 * 1024 ), 2), 'M') TOTAL_SIZE, CONCAT(ROUND(( DATA_FREE ) / ( 1024 * 1024 ), 2), 'M') DATA_FREE FROM information_schema.TABLES where table_schema = database() and ROUND(( DATA_FREE ) / ( 1024 * 1024 ), 2) > 0.00 ORDER BY DATA_FREE DESC; SELECT TABLE_NAME, ROUND(((Data_length - (TABLE_ROWS * Avg_row_length))/Data_length) * 100, 2) FRAG_Percent FROM information_schema.TABLES where table_schema = database() and TABLE_ROWS > 0 ...
Read more

How to Drop or Remove or Decommission a Database in Oracle

-
How to Drop or Remove or Decommission a Database in Oracle Database Decommission steps for Oracle 10G and 11g databases Note: ~~~~~~~~ Every organization has its own documented way of removing or decommissioning the active/running database that is supporting an Enterprise’s Application. Here I am presenting some general steps which may coincide with your organization’s standard operation procedure (SOP). 1)   Please get the required approval from Business/Customer to proceed for database decommissioning. 2)   Send the Notification to Business/Customer that we are going to decommission the database. (if required) 3)   Raise a Request for Storage and Backup team to take the required backup (provide all the details in the raised request) and to keep the Backup for a specified period of time, say for next 2 years, (That is called the backup retention period). Retention Period may be varied based on your business needs and SLA. The backup can...
Read more