DB-유

Diagnosing Deadlocks with SHOW ENGINE INNODB STATUS

· mysql, innodb, troubleshooting

When developers Slack me "the database is throwing deadlock errors", my first reaction used to be to blame the server. It's almost never the server. Two transactions each hold a lock the other needs, and InnoDB rolls back the one that has done less work. The application sees ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction, and if it retries, all is fine. The trouble starts when it happens hundreds of times an hour and nobody knows which two statements are colliding.

SHOW ENGINE INNODB STATUS records the last deadlock in detail, and innodb_print_all_deadlocks puts every one in the error log. You need PROCESS privilege, and this works on MySQL 5.6/5.7/8.0 and MariaDB 10.x.

Capture the deadlock

The status output only keeps the most recent deadlock. Make sure every deadlock is logged:

SET GLOBAL innodb_print_all_deadlocks = ON;

and persist it in /etc/my.cnf or /etc/mysql/mysql.conf.d/mysqld.cnf:

[mysqld]
innodb_print_all_deadlocks = 1

Then read the latest one:

SHOW ENGINE INNODB STATUS\G

Look for the section headed LATEST DETECTED DEADLOCK.

Reading the deadlock section

A typical example, trimmed:

------------------------
LATEST DETECTED DEADLOCK
------------------------
2019-07-10 22:41:03 0x7f3c2c1f1700
*** (1) TRANSACTION:
TRANSACTION 421873, ACTIVE 3 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s), undo log entries 1
MySQL thread id 8812, OS thread handle 139896432, query id 99127 10.0.1.30 shopapp updating
UPDATE stock SET qty = qty - 1 WHERE product_id = 42
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 61 page no 4 n bits 80 index PRIMARY of table `shop`.`stock` trx id 421873 lock_mode X locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION 421870, ACTIVE 5 sec starting index read
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1136, 3 row lock(s), undo log entries 2
MySQL thread id 8807, OS thread handle 139896112, query id 99131 10.0.1.31 shopapp updating
UPDATE stock SET qty = qty - 1 WHERE product_id = 17
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 61 page no 4 n bits 80 index PRIMARY of table `shop`.`stock` trx id 421870 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 61 page no 4 n bits 80 index PRIMARY of table `shop`.`stock` trx id 421870 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (1)

How to read it:

  • Each transaction block shows only the statement that was running at the moment of the deadlock, not the earlier statements that acquired the held locks. Transaction 2 holds a lock on stock from a previous UPDATE ... WHERE product_id = 42, which is not printed.
  • index PRIMARY of table shop.stock and lock_mode X locks rec but not gap tell you which index and what kind of lock. gap or insert intention locks point to range scans and inserts under REPEATABLE READ.
  • WE ROLL BACK TRANSACTION (1) is the victim; the other one continued.
  • undo log entries hints at how much each transaction had modified, which is what InnoDB uses to pick the victim.

The picture here is the classic one: two transactions updating the same rows in opposite order (42 then 17, and 17 then 42).

Finding the full transactions

The status only shows the last statement of each transaction, so correlate with the application. The thread id, client address and user identify the connection. I avoid leaving the general log on, but a few minutes is OK:

SET GLOBAL general_log = ON;
-- wait for a deadlock, then
SET GLOBAL general_log = OFF;

and grep the general log for the thread ids from the deadlock output. On 5.7 and later, performance_schema.events_statements_history_long gives the recent statements per thread without the general log:

SELECT t.PROCESSLIST_ID, s.SQL_TEXT
FROM performance_schema.events_statements_history_long s
JOIN performance_schema.threads t ON t.THREAD_ID = s.THREAD_ID
WHERE t.PROCESSLIST_ID IN (8812, 8807)
ORDER BY s.EVENT_ID;

Fixing the pattern

The fixes, in the order I reach for them:

  1. Lock rows in a consistent order. If every transaction updates stock rows sorted by product_id, the opposite-order deadlock cannot happen. In SQL: UPDATE stock SET qty = qty - 1 WHERE product_id IN (17, 42) ORDER BY product_id is not allowed for multi-table cases, but a preceding SELECT ... WHERE product_id IN (...) ORDER BY product_id FOR UPDATE acquires the locks in order.
  2. Keep transactions short. Do not hold a transaction open while calling an external API or waiting for user input.
  3. Add the missing index. UPDATE ... WHERE status = 'open' without an index on status locks every row it scans, not just the ones it changes.
  4. Switch to READ COMMITTED for sessions that only need it: SET SESSION transaction_isolation = 'READ-COMMITTED'. It removes most gap locks and is often the quickest win for insert-heavy deadlocks.
  5. Retry on 1213 in the application. A deadlock is a normal outcome; the retry loop should exist regardless of the fixes above.

Is it getting better?

Count deadlocks over time:

grep -c 'LATEST DETECTED DEADLOCK\|TRANSACTION.*deadlock' /var/log/mysqld.log

On 5.7+ the metric is also available directly:

SELECT * FROM sys.metrics WHERE Variable_name = 'lock_deadlocks';

or SHOW GLOBAL STATUS LIKE 'Innodb_deadlocks' on MariaDB. After the fix, the counter should stop increasing under the same load.

Things that trip people up

  • SHOW ENGINE INNODB STATUS is truncated at 64 KB of output by default; a deadlock involving many locks can be cut off. The error log with innodb_print_all_deadlocks is not truncated the same way.
  • ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction is not a deadlock. It is a plain lock wait that exceeded innodb_lock_wait_timeout (50 seconds by default). Look at information_schema.INNODB_LOCK_WAITS (5.7) or performance_schema.data_lock_waits (8.0) while it is happening.
  • Foreign keys take shared locks on parent rows; a deadlock between a child INSERT and a parent UPDATE is common and shows as lock mode S locks rec but not gap in the output.
  • Deadlock detection itself costs CPU on very high concurrency; innodb_deadlock_detect = OFF (5.7.15+) turns it off in favour of lock wait timeouts, but only do that with a low innodb_lock_wait_timeout.

I read the section from the bottom up: who was the victim, what each side waited for, what the other held. It nearly always turns out to be an ordering problem.