Reading InnoDB Deadlock Logs Like You Mean It

Deadlocks are one of those errors that teams learn to retry around rather than actually fix. I've inherited codebases where the retry logic had its own retry logic, and somewhere underneath it all was a two-query deadlock that could have been solved in an afternoon. The InnoDB error log tells you exactly what happened — most people just don't know how to read it.

What a Deadlock Actually Is (Not the Textbook Version)

Two transactions, each holding a lock the other one wants. InnoDB detects the cycle, picks a victim, rolls it back, and logs the whole thing. The surviving transaction completes. Your application gets a Deadlock found when trying to get lock; try restarting transaction error and, if you wrote your error handling properly, retries.

The retry is fine as a safety net. But if you're seeing deadlocks more than occasionally, you have a structural problem. Two queries are fighting over rows in a predictable order, and until you change one of them, they'll keep fighting.

The log tells you who they are.

Enabling the Right Logging

Before you can read the deadlock output, make sure MariaDB is capturing it. In /etc/mysql/mariadb.conf.d/50-server.cnf (or wherever your config lives):

[mysqld]
innodb_print_all_deadlocks = ON
log_error = /var/log/mysql/error.log

innodb_print_all_deadlocks is the critical one. Without it, you only get the most recent deadlock from SHOW ENGINE INNODB STATUS, and that gets overwritten the next time one happens. With it, every deadlock goes to the error log permanently. Restart MariaDB after changing this — it's not a dynamic variable on older versions.

You can also query the live status at any time:

SHOW ENGINE INNODB STATUS\G

Look for the LATEST DETECTED DEADLOCK section.

Anatomy of the Deadlock Block

Here's a representative deadlock block from the error log, lightly sanitized from something I pulled off a client's server last year. They were running an order fulfillment system and seeing deadlocks during high-volume batch processing:

2024-03-14 09:22:11 0x7f3a4c TRANSACTION:
TRANSACTION 48271934, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 1042, OS thread handle 139876543, query id 8821043 app_host 192.168.1.10 app_user updating
UPDATE orders SET status = 'processing', updated_at = NOW() WHERE id = 7841

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 312 page no 47 n bits 72 index PRIMARY of table `fulfillment`.`orders`
lock_mode X locks rec but not gap waiting

*** (2) TRANSACTION:
TRANSACTION 48271931, ACTIVE 0 sec fetching rows
mysql tables in use 2, locked 2
5 lock struct(s), heap size 1136, 4 row lock(s)
MySQL thread id 1039, OS thread handle 139876211, query id 8821038 app_host 192.168.1.10 app_user updating
UPDATE order_items SET reserved = 1 WHERE order_id = 7841

*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 312 page no 47 n bits 72 index PRIMARY of table `fulfillment`.`orders`
lock_mode X locks rec but not gap

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 318 page no 23 n bits 64 index PRIMARY of table `fulfillment`.`order_items`
lock_mode X locks rec but not gap waiting

*** WE ROLL BACK TRANSACTION (1)

Let me walk through what this is actually telling you.

Transaction 1 (the victim, rolled back): Thread 1042 is trying to UPDATE orders SET status = 'processing' WHERE id = 7841. It's waiting on an X lock on the primary key of orders for row 7841.

Transaction 2 (the survivor): Thread 1039 is running UPDATE order_items SET reserved = 1 WHERE order_id = 7841. It holds an X lock on orders row 7841, and it's waiting on a lock in order_items.

So transaction 2 locked an orders row first, then went after order_items. Transaction 1 came in and tried to lock the same orders row. Deadlock.

The fix here was obvious once I saw it: one code path was locking orders then order_items, and another was doing the same tables but in a different order because a developer had added a status update in a different part of the call stack. Standardize the lock order, deadlock disappears.

Parsing This in PHP

If you're seeing high deadlock frequency, it's worth pulling the error log programmatically and alerting on patterns. Here's a quick Laravel artisan command I use to scan for deadlock blocks and extract the query pairs:

<?php

namespace App\Console\Commands;

use Illuminate\Console\Command;

class ParseDeadlockLog extends Command
{
    protected $signature = 'db:deadlocks {--log=/var/log/mysql/error.log}';
    protected $description = 'Extract and summarize deadlock query pairs from the MariaDB error log';

    public function handle(): int
    {
        $logPath = $this->option('log');

        if (! file_exists($logPath)) {
            $this->error("Log file not found: {$logPath}");
            return self::FAILURE;
        }

        $content = file_get_contents($logPath);

        // Split on the deadlock header MariaDB writes
        $blocks = preg_split('/LATEST DETECTED DEADLOCK|InnoDB: transactions deadlock detected/', $content);

        // Also catch the innodb_print_all_deadlocks format
        $deadlockPattern = '/\*{3}\s*\(1\)\s*TRANSACTION.*?WE ROLL BACK TRANSACTION/s';
        preg_match_all($deadlockPattern, $content, $matches);

        if (empty($matches[0])) {
            $this->info('No deadlock blocks found.');
            return self::SUCCESS;
        }

        $this->info(count($matches[0]) . ' deadlock(s) found.');
        $this->line('');

        foreach ($matches[0] as $i => $block) {
            $this->line("--- Deadlock " . ($i + 1) . " ---");

            // Pull the query lines — they appear after the thread/query id line
            $queryPattern = '/query id \d+ [\w\.]+ [\w\.]+ [\w]+\n(.+?)\n/m';
            preg_match_all($queryPattern, $block, $queries);

            foreach ($queries[1] as $j => $query) {
                $label = $j === 0 ? 'TX1 (victim)' : 'TX2 (survivor)';
                $this->line("  {$label}: " . trim($query));
            }

            $this->line('');
        }

        return self::SUCCESS;
    }
}

Run it with php artisan db:deadlocks and you get a clean summary of every deadlock pair in the log. I've piped this into a Slack webhook on clients where the DBAs need a morning report without SSH access to the server.

The Gotchas That Will Bite You

The log shows the symptom, not always the root cause. The query you see waiting is the one that got killed. But the real problem is often a query further up in the surviving transaction — one that grabbed a lock early and held it while doing unrelated work. Look at what Transaction 2 holds, not just what it's waiting for.

WHERE order_id = 7841 with a non-indexed foreign key will gap-lock an entire range. If order_id on order_items doesn't have an index, InnoDB has to do a full scan and may lock far more rows than you expect. I've seen deadlocks that looked like single-row conflicts turn out to be table-near-full-scan gap locks. Check EXPLAIN on the queries you find in the deadlock log.

Transaction 1 in the log is not always the first one that started. InnoDB picks the cheapest victim to roll back, which usually means the one with fewer rows modified. Don't assume transaction ordering from the log block order.

The timestamps lie a little. MariaDB logs the deadlock time, not the time each transaction started. Both transactions had ACTIVE 0 sec in my example above, which sounds like they started simultaneously. They didn't. 0 sec just means under a second. If you need actual start times, correlate with your slow query log or application-level tracing.

innodb_print_all_deadlocks can fill your disk. On a system with a persistent deadlock bug in production, I've seen this generate gigabytes of log in hours. Enable it to diagnose, set up log rotation (logrotate), and consider disabling it once you've fixed the problem.

When I'd Dig Into This

Anytime I see Deadlock found when trying to get lock in application logs more than a handful of times per day, I go straight to the InnoDB error log. Retrying the transaction is not a fix — it's a band-aid that hides a lock ordering problem that will eventually cause real latency under load.

I'd also do a deadlock audit before any significant schema change on a busy table. Add an index, change a foreign key, add a new query that touches the same rows — these can all introduce deadlock patterns that weren't there before. Having baseline deadlock log output makes regression obvious.

I wouldn't bother with this level of analysis for a dev/staging environment that sees minimal concurrent load. Deadlocks are inherently a concurrency phenomenon — they often don't reproduce unless you have real traffic hitting the same rows at the same time.

Fixing the Pattern, Not the Symptom

Once you've identified the query pair, the fix usually falls into one of three buckets: standardize lock acquisition order across all code paths touching those tables, reduce the transaction scope so locks are held for less time, or add an index so InnoDB locks exactly the rows it needs instead of a range.

The retry loop can stay — it's a good safety net. But if you've read the log and found your deadlock pair, you have enough information to make it fire rarely instead of constantly. Do that work. Future-you will be grateful.