mysql lock wait timeout exceeded, try restarting transaction

Question

Hi All, I am getting following error while I am trying to execute a stored procedure which has one update statement.

Below is the INNODB STATUS OUTPUT after the error:

=====================================
090828 12:54:36 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 33 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1796, signal count 1794
Mutex spin waits 0, rounds 3036, OS waits 85
RW-shared spins 3538, OS waits 1653; RW-excl spins 56, OS waits 55
------------
TRANSACTIONS
------------
Trx id counter 0 1289747
Purge done for trx's n:o < 0 1289739 undo n:o < 0 0
History list length 85
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 1289744, not started, process no 2986, OS thread id 140445151164752
MySQL thread id 462, query id 64252 Terminator 192.168.1.1 mysqluser
---TRANSACTION 0 0, not started, process no 2986, OS thread id 140445155424592
MySQL thread id 522, query id 64273 192.168.1.2 sysuser
SHOW ENGINE INNODB STATUS
---TRANSACTION 0 1289710, not started, process no 2986, OS thread id 140445132179792
MySQL thread id 490, query id 63941 Fembot 192.168.1.5 mysqluser
---TRANSACTION 0 1289743, not started, process no 2986, OS thread id 140445141580112
MySQL thread id 496, query id 64247 192.168.1.2 sysuser
---TRANSACTION 0 1289639, not started, process no 2986, OS thread id 140445132978512
MySQL thread id 488, query id 63512 Fembot 192.168.1.5 mysqluser
---TRANSACTION 0 1289742, not started, process no 2986, OS thread id 140445134043472
MySQL thread id 461, query id 64242 Terminator 192.168.1.1 mysqluser
---TRANSACTION 0 1289340, not started, process no 2986, OS thread id 140445131114832
MySQL thread id 404, query id 59793 192.168.1.4 mysqluser
---TRANSACTION 0 1289678, not started, process no 2986, OS thread id 140445139450192
MySQL thread id 179, query id 63763 192.168.1.4 mysqluser
---TRANSACTION 0 1289672, not started, process no 2986, OS thread id 140445143976272
MySQL thread id 150, query id 63745 192.168.1.4 mysqluser
---TRANSACTION 0 1289651, not started, process no 2986, OS thread id 140445138385232
MySQL thread id 183, query id 63563 192.168.1.4 mysqluser
---TRANSACTION 0 1289706, not started, process no 2986, OS thread id 140445149833552
MySQL thread id 173, query id 63929 192.168.1.4 mysqluser
---TRANSACTION 0 1289676, not started, process no 2986, OS thread id 140445149034832
MySQL thread id 171, query id 63757 192.168.1.4 mysqluser
---TRANSACTION 0 1289708, not started, process no 2986, OS thread id 140445138917712
MySQL thread id 181, query id 63935 192.168.1.4 mysqluser
---TRANSACTION 0 1289732, not started, process no 2986, OS thread id 140445145307472
MySQL thread id 169, query id 64159 192.168.1.4 mysqluser
---TRANSACTION 0 1289488, not started, process no 2986, OS thread id 140445143710032
MySQL thread id 152, query id 62259 192.168.1.4 mysqluser
---TRANSACTION 0 1289492, not started, process no 2986, OS thread id 140445139982672
MySQL thread id 177, query id 62276 192.168.1.4 mysqluser
---TRANSACTION 0 1287321, not started, process no 2986, OS thread id 140445137586512
MySQL thread id 186, query id 11487 192.168.1.4 mysqluser
---TRANSACTION 0 1287320, not started, process no 2986, OS thread id 140445137852752
MySQL thread id 185, query id 11475 192.168.1.4 mysqluser
---TRANSACTION 0 1289653, not started, process no 2986, OS thread id 140445142911312
MySQL thread id 167, query id 63576 192.168.1.4 mysqluser
---TRANSACTION 0 1289696, not started, process no 2986, OS thread id 140445144508752
MySQL thread id 147, query id 63900 192.168.1.4 mysqluser
---TRANSACTION 0 1287290, not started, process no 2986, OS thread id 140445140248912
MySQL thread id 176, query id 11326 192.168.1.4 mysqluser
---TRANSACTION 0 1287289, not started, process no 2986, OS thread id 140445149301072
MySQL thread id 175, query id 11314 192.168.1.4 mysqluser
---TRANSACTION 0 1289643, not started, process no 2986, OS thread id 140445150632272
MySQL thread id 145, query id 63536 192.168.1.4 mysqluser
---TRANSACTION 0 1287255, not started, process no 2986, OS thread id 140445140515152
MySQL thread id 156, query id 11079 192.168.1.4 mysqluser
---TRANSACTION 0 1289694, not started, process no 2986, OS thread id 140445145839952
MySQL thread id 65, query id 63894 192.168.1.3 mysqluser
---TRANSACTION 0 1286467, not started, process no 2986, OS thread id 140445146106192
MySQL thread id 64, query id 3652 192.168.1.3 mysqluser
---TRANSACTION 0 1286466, not started, process no 2986, OS thread id 140445146372432
MySQL thread id 63, query id 3640 192.168.1.3 mysqluser
---TRANSACTION 0 1289731, not started, process no 2986, OS thread id 140445157288272
MySQL thread id 20, query id 64155 Fembot 192.168.1.5 mysqluser
---TRANSACTION 0 1289746, ACTIVE 0 sec, process no 2986, OS thread id 140445151697232 starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1216, 6 row lock(s)
MySQL thread id 464, query id 64270 Terminator 192.168.1.1 mysqluser Updating
Update test
         Set email = 1
         Where testid =  NAME_CONST('InputtestID',5)
------- TRX HAS BEEN WAITING 0 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 2952 n bits 176 index `PRIMARY` of table `DB`.`test` trx id 0 1289746 lock_mode X locks rec but not gap waiting
Record lock, heap no 6 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
 0: len 8; hex 0000000000000005; asc         ;; 1: len 6; hex 00000013ae09; asc       ;; 2: len 7; hex 000000066629ae; asc     f) ;; 3: len 27; hex 796f67696e692e6b756c6b61726e69407961686f6f2e636f2e696e; asc [email protected];; 4: len 6; hex 6950686f6e65; asc iPhone;; 5: len 28; hex 4e644a4b676d5661637068666b4868476c4761525a502b385a44303d; asc NdJKgmVacphfkHhGlGaRZP+8ZD0=;; 6: len 28; hex 577a786b6f4956532f735a374b4559732b4b6b794c39307a4a35513d; asc WzxkoIVS/sZ7KEYs+KkyL90zJ5Q=;; 7: len 1; hex 81; asc  ;; 8: len 1; hex 80; asc  ;; 9: len 8; hex 80001245b60a4c53; asc    E  LS;; 10: SQL NULL; 11: len 30; hex 626635336237613736306633353462653665383834666666303936626233; asc bf53b7a760f354be6e884fff096bb3;...(truncated);

------------------
---TRANSACTION 0 1289745, ACTIVE 0 sec, process no 2986, OS thread id 140445136972112
10 lock struct(s), heap size 3024, 6 row lock(s)
MySQL thread id 463, query id 64255 Terminator 192.168.1.1 mysqluser
--------
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
20795 OS file reads, 2556 OS file writes, 1210 OS fsyncs
3.12 reads/s, 37221 avg bytes/read, 0.18 writes/s, 0.12 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 0, seg size 2,
0 inserts, 0 merged recs, 0 merges
Hash table size 17393, node heap has 1 buffer(s)
0.00 hash searches/s, 0.61 non-hash searches/s
---
LOG
---
Log sequence number 0 287498463
Log flushed up to   0 287498463
Last checkpoint at  0 287498463
0 pending log writes, 0 pending chkp writes
913 log i/o's done, 0.06 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 31312994; in additional pool allocated 1048576
Dictionary memory allocated 8764592
Buffer pool size   512
Free buffers       0
Database pages     511
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 45969, created 76, written 1658
7.09 reads/s, 0.00 creates/s, 0.09 writes/s
Buffer pool hit rate 977 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 2986, id 140445169375568, state: sleeping
Number of rows inserted 2367, updated 662, deleted 2330, read 30234862
0.00 inserts/s, 0.03 updates/s, 0.00 deletes/s, 1828.97 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

also this is the slow_query_logs:

# Query_time: 51.156942  Lock_time: 0.000008 Rows_sent: 0  Rows_examined: 5
SET timestamp=1251444327;
CALL SP_test(5,'[email protected]');

this is the update statement of procedure:

Update test
set testflag = 1
where testid = 5;

Please let me know

Answer 1

Hmm. For the few information you provided (I miss at least the table declaration);

1. I suggest checking if 'testid' has an index. If not, it may take too long to find the lines.
2. The table contains to many entries for the hardware you use ;)
3. The slow query could be a red herring, so that other queries slow down your database and this write statement has to wait. (But I don't know what is going on on your db)
4. You may have to many exclusive locks on your tables that prevent them from writing (updating)

Please provide more problem-centric information that makes it easier to help.

Answer 2

Without knowing the cause, I can propose you this workaround:

Increase the value of this MySQL parameter (TransactionDeadlockDetectionTimeout) in the config file (my.cnf).

It could help but will not fix the cause of the locked table.