How to troubleshoot MySQL `ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction`

Question

I seem to not be able extract any helpful information from MySQL to aid my debugging for this error: ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction. Can you help me find some?

Reproduction:

One process does something like this:

start transaction;
update cfgNodes set name="foobar" where ID=29;

and just sits there (not committing, not rolling back). This is clearly the culprit - the process that is hogging the lock because of a long-running transaction - the offender I'm trying to find.

Another process tries:

-- The next line just prevents you from having to wait 50 seconds
set innodb_lock_wait_timeout=1;

update cfgNodes set name="foobar" where ID=29;

This second process gets ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction (after innodb_lock_wait_timeout, default 50secs)

How do I find any information about the culprit?

Answer 1

The standard recommended sources are of little help:

INFORMATION_SCHEMA.INNODB_TRX shows the transaction but not much about it that can help me find it. Only that 1 table is locked (in this bogus tiny example), and that trx_mysql_thread_id is 4093.

mysql> select * from INFORMATION_SCHEMA.INNODB_TRX\G
*************************** 1. row ***************************
                    trx_id: 280907
                 trx_state: RUNNING
               trx_started: 2018-11-30 00:35:06
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 3
       trx_mysql_thread_id: 4093
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1136
           trx_rows_locked: 1
         trx_rows_modified: 1
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
1 row in set (0.00 sec)

INFORMATION_SCHEMA.INNODB_LOCKS is empty, which makes sense given the documentation, because there is only one transaction and currently nobody waiting for any locks. Also INNODB_LOCKS is deprecated anyway.

SHOW ENGINE INNODB STATUS is useless: cfgNodes is not mentioned at all

SHOW FULL PROCESSLIST is empty, because the culprit is not actually running a query right now.

But now remember the trx_mysql_thread_id from before? We can use that to see the queries executed in that transaction:

mysql> SELECT SQL_TEXT
    -> FROM performance_schema.events_statements_history ESH,
    ->      performance_schema.threads T
    -> WHERE ESH.THREAD_ID = T.THREAD_ID
    ->   AND ESH.SQL_TEXT IS NOT NULL
    ->   AND T.PROCESSLIST_ID = 4093
    -> ORDER BY ESH.EVENT_ID LIMIT 10;
+-----------------------------------------------+
| SQL_TEXT                                      |
+-----------------------------------------------+
| select @@version_comment limit 1              |
| start transaction                             |
| update cfgNodes set name="foobar" where ID=29 |
+-----------------------------------------------+
3 rows in set (0.00 sec)

Voila - we now see a history of the last 10 queries for each of the remaining transactions allowing us to find the culprit.