How to debug Lock wait timeout exceeded on MySQL?

Question

In my production error logs I occasionally see:

SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded; try restarting transaction

I know which query is trying to access the database at that moment but is there a way to find out which query had the lock at that precise moment?

Solution 1

What gives this away is the word transaction. It is evident by the statement that the query was attempting to change at least one row in one or more InnoDB tables.

Since you know the query, all the tables being accessed are candidates for being the culprit.

From there, you should be able to run SHOW ENGINE INNODB STATUS\G

You should be able to see the affected table(s)

You get all kinds of additional Locking and Mutex Information.

Here is a sample from one of my clients:

mysql> show engine innodb status\G
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
110514 19:44:14 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 9014315, signal count 7805377
Mutex spin waits 0, rounds 11487096053, OS waits 7756855
RW-shared spins 722142, OS waits 211221; RW-excl spins 787046, OS waits 39353
------------------------
LATEST FOREIGN KEY ERROR
------------------------
110507 21:41:35 Transaction:
TRANSACTION 0 606162814, ACTIVE 0 sec, process no 29956, OS thread id 1223895360 updating or deleting, thread declared inside InnoDB 499
mysql tables in use 1, locked 1
14 lock struct(s), heap size 3024, 8 row lock(s), undo log entries 1
MySQL thread id 3686635, query id 124164167 10.64.89.145 viget updating
DELETE FROM file WHERE file_id in ('6dbafa39-7f00-0001-51f2-412a450be5cc' )
Foreign key constraint fails for table `backoffice`.`attachment`:
,
  CONSTRAINT `attachment_ibfk_2` FOREIGN KEY (`file_id`) REFERENCES `file` (`file_id`)
Trying to delete or update in parent table, in index `PRIMARY` tuple:
DATA TUPLE: 17 fields;
 0: len 36; hex 36646261666133392d376630302d303030312d353166322d343132613435306265356363; asc 6dbafa39-7f00-0001-51f2-412a450be5cc;; 1: len 6; hex 000024214f7e; asc   $!O~;; 2: len 7; hex 000000400217bc; asc    @   ;; 3: len 2; hex 03e9; asc   ;; 4: len 2; hex 03e8; asc   ;; 5: len 36; hex 65666635323863622d376630302d303030312d336632662d353239626433653361333032; asc eff528cb-7f00-0001-3f2f-529bd3e3a302;; 6: len 40; hex 36646234376337652d376630302d303030312d353166322d3431326132346664656366352e6d7033; asc 6db47c7e-7f00-0001-51f2-412a24fdecf5.mp3;; 7: len 21; hex 416e67656c73204e6f7720436f6e666572656e6365; asc Angels Now Conference;; 8: len 34; hex 416e67656c73204e6f7720436f6e666572656e6365204a756c7920392c2032303131; asc Angels Now Conference July 9, 2011;; 9: len 1; hex 80; asc  ;; 10: len 8; hex 8000124a5262bdf4; asc    JRb  ;; 11: len 8; hex 8000124a57669dc3; asc    JWf  ;; 12: SQL NULL; 13: len 5; hex 8000012200; asc    " ;; 14: len 1; hex 80; asc  ;; 15: len 2; hex 83e8; asc   ;; 16: len 4; hex 8000000a; asc     ;;

But in child table `backoffice`.`attachment`, in index `PRIMARY`, there is a record:
PHYSICAL RECORD: n_fields 6; compact format; info bits 0
 0: len 30; hex 36646261666133392d376630302d303030312d353166322d343132613435; asc 6dbafa39-7f00-0001-51f2-412a45;...(truncated); 1: len 30; hex 38666164663561652d376630302d303030312d326436612d636164326361; asc 8fadf5ae-7f00-0001-2d6a-cad2ca;...(truncated); 2: len 6; hex 00002297b3ff; asc   "   ;; 3: len 7; hex 80000040070110; asc    @   ;; 4: len 2; hex 0000; asc   ;; 5: len 30; hex 416e67656c73204e6f7720436f6e666572656e636520446f63756d656e74; asc Angels Now Conference Document;;

------------
TRANSACTIONS
------------
Trx id counter 0 620783814
Purge done for trx's n:o < 0 620783800 undo n:o < 0 0
History list length 35
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1192212800
MySQL thread id 5341758, query id 189708501 127.0.0.1 lwdba
show innodb status
---TRANSACTION 0 620783788, not started, process no 29956, OS thread id 1196472640
MySQL thread id 5341773, query id 189708353 10.64.89.143 viget
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1223895360
MySQL thread id 5341667, query id 189706152 10.64.89.145 viget
---TRANSACTION 0 0, not started, process no 29956, OS thread id 1227888960
MySQL thread id 5341556, query id 189699857 172.16.135.63 lwdba
---TRANSACTION 0 620781112, not started, process no 29956, OS thread id 1222297920
MySQL thread id 5341511, query id 189696265 10.64.89.143 viget
---TRANSACTION 0 620783736, not started, process no 29956, OS thread id 1229752640
MySQL thread id 5339005, query id 189707998 10.64.89.144 viget
---TRANSACTION 0 620783785, not started, process no 29956, OS thread id 1198602560
MySQL thread id 5337583, query id 189708349 10.64.89.145 viget
---TRANSACTION 0 620783469, not started, process no 29956, OS thread id 1224161600
MySQL thread id 5333500, query id 189708478 10.64.89.144 viget
---TRANSACTION 0 620781240, not started, process no 29956, OS thread id 1198336320
MySQL thread id 5324256, query id 189708493 10.64.89.145 viget
---TRANSACTION 0 617458223, not started, process no 29956, OS thread id 1195141440
MySQL thread id 736, query id 175038790 Has read all relay log; waiting for the slave I/O thread to update it
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
519878 OS file reads, 18962880 OS file writes, 13349046 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 6.25 writes/s, 4.50 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 1190, seg size 1192,
174800 inserts, 174800 merged recs, 54439 merges
Hash table size 35401603, node heap has 35160 buffer(s)
0.50 hash searches/s, 11.75 non-hash searches/s
---
LOG
---
Log sequence number 28 1235093534
Log flushed up to   28 1235093534
Last checkpoint at  28 1235091275
0 pending log writes, 0 pending chkp writes
12262564 log i/o's done, 3.25 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 18909316674; in additional pool allocated 1048576
Dictionary memory allocated 2019632
Buffer pool size   1048576
Free buffers       175763
Database pages     837653
Modified db pages  6
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 770138, created 108485, written 7795318
0.00 reads/s, 0.00 creates/s, 4.25 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 29956, id 1185823040, state: sleeping
Number of rows inserted 6453767, updated 4602534, deleted 3638793, read 388349505551
0.25 inserts/s, 1.25 updates/s, 0.00 deletes/s, 2.75 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set, 1 warning (0.00 sec)

You should consider increasing the lock wait timeout value for InnoDB by setting the innodb_lock_wait_timeout, default is 50 sec

mysql> show variables like 'innodb_lock_wait_timeout';
+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_lock_wait_timeout | 50    |
+--------------------------+-------+
1 row in set (0.01 sec)

You can set it to higher value in /etc/my.cnf permanently with this line

[mysqld]
innodb_lock_wait_timeout=120

and restart mysql. If you cannot restart mysql at this time, run this:

SET GLOBAL innodb_lock_wait_timeout = 120; 

You could also just set it for the duration of your session

SET innodb_lock_wait_timeout = 120; 

followed by your query

Solution 2

As someone mentioned in one of the many SO threads concerning this problem: Sometimes the process that has locked the table shows up as sleeping in the processlist! I was tearing my hair out until I killed all the sleeping threads that were open in the database in question (none were active at the time). That finally unlocked the table and let the update query run.

The commenter said something akin to "Sometimes a MySQL thread locks a table, then sleeps while it waits for something non-MySQL-related to happen."

After re-re-reviewing the show engine innodb status log (once I'd tracked down the client responsible for the lock), I noticed the stuck thread in question was listed at the very bottom of the transaction list, beneath the active queries that were about to error out because of the frozen lock:

------------------
---TRANSACTION 2744943820, ACTIVE 1154 sec(!!)
2 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 276558, OS thread handle 0x7f93762e7710, query id 59264109 [ip] [database] cleaning up
Trx read view will not see trx with id >= 2744943821, sees < 2744943821

(unsure if the "Trx read view" message is related to the frozen lock, but unlike the other active transactions, this one does not show up with the query that was issued and instead claims the transaction is "cleaning up," yet has multiple row locks)

The moral of the story is that a transaction can be active even though the thread is sleeping.

Solution 3

The more contention you have, the greater the chance of deadlocks, which a DB engine will resolve by time-outing one of the deadlocked transactions.

Also, long-running transactions that have modified (e.g. UPDATE or DELETE) a large number of entries are more likely to generate conflicts with other transactions.

Although InnoDB MVCC, you can still request explicit locks using the FOR UPDATE clause. However, unlike other popular DBs (Oracle, MSSQL, PostgreSQL, DB2), MySQL uses REPEATABLE_READ as the default isolation level.

Now, the locks that you acquired (either by modifying rows or using explicit locking) are held for the duration of the currently running transaction. If you want a good explanation of the difference between REPEATABLE_READ and READ COMMITTED in regards to locking, please read this Percona article.

In REPEATABLE READ every lock acquired during a transaction is held for the duration of the transaction.

In READ COMMITTED the locks that did not match the scan are released after the STATEMENT completes.

...

This means that in READ COMMITTED other transactions are free to update rows that they would not have been able to update (in REPEATABLE READ) once the UPDATE statement completes.

Therefore: The more restrictive the isolation level (REPEATABLE_READ, SERIALIZABLE) the greater the chance of deadlock. This is not an issue "per se", it's a trade-off.

You can get very good results with READ_COMMITTED, as you need application-level lost update prevention when using logical transactions that span over multiple HTTP requests. The optimistic locking approach targets lost updates that might happen even if you use the SERIALIZABLE isolation level while reducing the lock contention by allowing you to use READ_COMMITTED.

Solution 4

For the record, the lock wait timeout exception happens also when there is a deadlock and MySQL cannot detect it, so it just times out. Another reason might be an extremely long running query, which is easier to solve/repair, however, and I will not describe this case here.

MySQL is usually able to deal with deadlocks if they are constructed "properly" within two transactions. MySQL then just kills/rollback the one transaction that owns fewer locks (is less important as it will impact less rows) and lets the other one finish.

Now, let's suppose there are two processes A and B and 3 transactions:

Process A Transaction 1: Locks X
Process B Transaction 2: Locks Y
Process A Transaction 3: Needs Y => Waits for Y
Process B Transaction 2: Needs X => Waits for X
Process A Transaction 1: Waits for Transaction 3 to finish

(see the last two paragraph below to specify the terms in more detail)

=> deadlock 

This is a very unfortunate setup because MySQL cannot see there is a deadlock (spanned within 3 transactions). So what MySQL does is ... nothing! It just waits, since it does not know what to do. It waits until the first acquired lock exceeds the timeout (Process A Transaction 1: Locks X), then this will unblock the Lock X, which unlocks Transaction 2 etc.

The art is to find out what (which query) causes the first lock (Lock X). You will be able to see easily (show engine innodb status) that Transaction 3 waits for Transaction 2, but you will not see which transaction Transaction 2 is waiting for (Transaction 1). MySQL will not print any locks or query associated with Transaction 1. The only hint will be that at the very bottom of the transaction list (of the show engine innodb status printout), you will see Transaction 1 apparently doing nothing (but in fact waiting for Transaction 3 to finish).

The technique for how to find which SQL query causes the lock (Lock X) to be granted for a given transaction that is waiting is described here Tracking MySQL query history in long running transactions

If you are wondering what the process and the transaction is exactly in the example. The process is a PHP process. Transaction is a transaction as defined by innodb-trx-table. In my case, I had two PHP processes, in each I started a transaction manually. The interesting part was that even though I started one transaction in a process, MySQL used internally in fact two separate transactions (I don't have a clue why, maybe some MySQL dev can explain).

MySQL is managing its own transactions internally and decided (in my case) to use two transactions to handle all the SQL requests coming from the PHP process (Process A). The statement that Transaction 1 is waiting for Transaction 3 to finish is an internal MySQL thing. MySQL "knew" the Transaction 1 and Transaction 3 were actually instantiated as part of one "transaction" request (from Process A). Now the whole "transaction" was blocked because Transaction 3 (a subpart of "transaction") was blocked. Because "transaction" was not able to finish the Transaction 1 (also a subpart of the "transaction") was marked as not finished as well. This is what I meant by "Transaction 1 waits for Transaction 3 to finish".

Solution 5

The big problem with this exception is that its usually not reproducible in a test environment and we are not around to run innodb engine status when it happens on prod. So in one of the projects I put the below code into a catch block for this exception. That helped me catch the engine status when the exception happened. That helped a lot.

Statement st = con.createStatement();
ResultSet rs =  st.executeQuery("SHOW ENGINE INNODB STATUS");
while(rs.next()){
    log.info(rs.getString(1));
    log.info(rs.getString(2));
    log.info(rs.getString(3));
}

View more solutions

Comments

[kommradHomer]

I heavily suggest everyone to give Eirik 's answer a shot

[Max Alexander Hanna]

Possible duplicate of How to overcome Failure getting record lock on a record from table

[Timo Huovinen]

For the built-in InnoDB, innodb_lock_wait_timeout variable can be set only at server startup. For InnoDB Plugin, it can be set at startup or changed at runtime, and has both global and session values.

[Manish Sapkal]

Hi @rolandomysqldba, can you please give suggestion me on my this post : stackoverflow.com/questions/18267565/…

[Brad Mace]

this tool is now part of the Percona toolkit

[Iulian Onofrei]

I get this error when trying to run the first query: SQL Error (1064): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near '\G' at line 1

[ColinM]

Isn't lock wait timeout different than deadlock? E.g. if one thread holds a lock for 60 seconds for legitimate reasons then the lock wait timeout may occur. Is it not true that if there is really a deadlock MySQL will detect this and kill a transaction instantly and this is not related to lock wait timeout?

[Vlad Mihalcea]

You are right. The DB detects the dead-lock after timeout and kills one waiting process, so one transaction wins while the other fails. But the longer you hold a lock the less scalable the application gets. Even if you don't run into dead-locks you will still increase the serializable part of your application runtime behavior.

[Pacerier]

@Rolando, What's the point of changing /etc/my.cnf if we can change it using SET GLOBAL innodb_lock_wait_timeout = 120;? Why will someone even bother changing the cnf file?

[RolandoMySQLDBA]

@Pacerier Every time mysqld is restarted, you have to run SET GLOBAL innodb_lock_wait_timeout = 120; again. If /etc/my.cnf has the option, innodb_lock_wait_timeout is set for you. Not everyone has SUPER privilege to change it globally for everybody else (dev.mysql.com/doc/refman/5.6/en/…)

[kommradHomer]

i can't say you saved my life , but you set my mind on peace for sure. Reading your answer , i found a creepy thread that's active for 3260 seconds , and not showing up anywhere. after killing it , all my problems were solved !

[Wodin]

How do you know it's 5341773? I don't see what distinguishes that one from the others.

[Ellert van Koperen]

No it is probably not that threadID, it was an example. You have to find the thread IDs from the "show engine innodb status\G" command, and figure out which one is the one that is blocking the database.

[Wodin]

Thanks. So in other words there's no way to tell which one it is without e.g. killing them one by one?

[Ellert van Koperen]

In the list of transactions you can see which ones are running and for how long. So no need to kill them off one by one, that list usually gives you a pretty good idea of what is going on.

[bigtex777]

This was my problem. A sleeping transaction with time of 20,000 seconds that was preventing Delayed Job in a Rails app from running properly. Thanks @Eirik

[mpen]

In my case, a rogue server was hanging onto my "user" record which was preventing me from logging into my own software. Neato! I advise others to check their Process List for any connections that have been open for a long time.

[Jay Paroline]

Lock wait timeouts are not the same as deadlocks, specifically innodb does not show any information about them because they are not detected deadlocks, so I do not think pt-deadlock-logger is any help.

[Andrei Sura]

Lock timeouts and deadlocks are related though - see dev.mysql.com/doc/refman/5.7/en/innodb-deadlock-detection.ht‌​ml

[Hussain]

How to solve this for RDS? What alarms need to be set to catch this issue?

[thenickdude]

@IulianOnofrei the \G character is a special feature of the MySQL command line and changes the way the output is displayed. For other MySQL clients just use a regular semicolon instead.

[patrickdavey]

Any idea why a sleeping transaction doesn't get killed off anyway? Like, is there a timeout you can set that a transaction must finish within?

[Eric L.]

My last line there might help "The moral of the story is that a transaction can be active even though the thread is sleeping." So the server is waiting for something to happen outside of its control and actively doing... something while it waits that keeps the transaction active. It doesn't appear that any of the time-related settings can stop that sort of transaction automatically.

[nickang]

Other commands that might be helpful in your search for locking transactions: show processlist; to show an exhaustive list of processes currently being executed, which is nice because it's a condensed version of show engine innodb status\g. Also, if your db is on an Amazon RDS instance, you can use CALL mysql.rds_kill(<thread_id>); to kill threads. It has higher permissions I think, because it allowed me to kill more processes than plain kill <thread_id>; - note these should be run within MySQL CLI

[EscapeNetscape]

would it not be better to decrease innodb_lock_wait_timeout so that mysql kills it earlier instead of later?

[Isaiah]

This did it. I would like to add that in our case the Time was minimal on the sleeping thread further hiding the problem. A sort on the id column showed two processes 25K lower than all of the others. A kill command on both solved our problem.

[Erin Schoonover]

Anyone have a source for this - maybe a documentation page stating the locks are placed before COMMIT phase? I couldn't find anything, despite seeing this exact issue and it being cleared up by killing the sleeping thread that was holding locks.

[Soheil Rahsaz]

Upvote For explaining what was happening to me, but does anyone have any solution to avoid that?

[Steen Schütt]

Slow query logs could be helpful though, and Percona also maintains the pt-query-digest program in their toolkit, which can summarize the logs for you.