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

User · Answer

Here is what I ultimately had to do to figure out what "other query" caused the lock timeout problem. In the application code, we track all pending database calls on a separate thread dedicated to this task. If any DB call takes longer than N-seconds (for us it's 30 seconds) we log:

-- Pending InnoDB transactions
SELECT * FROM information_schema.innodb_trx ORDER BY trx_started; 

-- Optionally, log what transaction holds what locks
SELECT * FROM information_schema.innodb_locks;

With above, we were able to pinpoint concurrent queries that locked the rows causing the deadlock. In my case, they were statements like INSERT ... SELECT which unlike plain SELECTs lock the underlying rows. You can then reorganize the code or use a different transaction isolation like read uncommitted.

Good luck!

User · Answer

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

User · Answer

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   gt  Waits for Y Process B Transaction 2  Needs X   gt  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     gt  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

User · Answer

You can use   show full processlist   which will list all the connections in MySQL and the current state of connection as well as the query being executed  There s also a shorter variant show processlist  which displays the truncated query as well as the connection stats

User · Answer

Extrapolating from Rolando s answer above  it is these that are blocking your query   ---TRANSACTION 0 620783788  not started  process no 29956  OS thread id 1196472640 MySQL thread id 5341773  query id 189708353 10 64 89 143 viget   If you need to execute your query and can not wait for the others to run  kill them off using the MySQL thread id   kill 5341773  lt replace with your thread id gt     from within mysql  not the shell  obviously   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

User · Answer

Due to the popularity of MySQL  there s no wonder Lock wait timeout exceeded  try restarting transaction exception gets so much attention on SO  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  quot per se quot   it s a trade-off  You can get very good results with READ COMMITED  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 COMMITED

User · Answer

If you re using JDBC  then you have the option includeInnodbStatusInDeadlockExceptions true  https   dev mysql com doc connector-j 8 0 en connector-j-reference-configuration-properties html

User · Answer

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 gt  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     quot     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    quot       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  lt  0 620783800 undo n o  lt  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 gt  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

User · Answer

Activate MySQL general log  disk intensive  and use mysql analyse general log pl to extract long running transactions  for example with       --min-duration your innodb lock wait timeout value   Disable general log after that

User · Answer

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  gt   2744943821  sees  lt  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

User · Answer

Take a look at the man page of the pt-deadlock-logger utility   brew install percona-toolkit pt-deadlock-logger --ask-pass server name   It extracts information from the engine innodb status mentioned above and also  it can be used to create a daemon which runs every 30 seconds

[mysql] How to debug Lock wait timeout exceeded on MySQL?

Examples related to mysql

Examples related to debugging

Examples related to transactions

Examples related to innodb

Examples related to acid