如何解決和調試MySQL錯誤：ER_LOCK_WAIT_TIMEOUT：超出鎖定等待超時;嘗試重新啓動交易

Question

我已經在這裏閱讀了幾篇文章，但仍不明白我該如何解決錯誤。另外我如何解碼show engine innodb status輸出。我懷疑它是一個死鎖或者一個永遠不會提交/回滾的事務，導致永遠持有這個鎖（這可能嗎？）。

# show engine innodb status; 
===================================== 
2015-09-27 04:43:54 2b9cf470f700 INNODB MONITOR OUTPUT 
===================================== 
Per second averages calculated from the last 33 seconds 
----------------- 
BACKGROUND THREAD 
----------------- 
srv_master_thread loops: 16140 srv_active, 0 srv_shutdown, 3941554 srv_idle 
srv_master_thread log flush and writes: 3957687 
---------- 
SEMAPHORES 
---------- 
OS WAIT ARRAY INFO: reservation count 25915 
OS WAIT ARRAY INFO: signal count 25874 
Mutex spin waits 1675, rounds 50212, OS waits 1581 
RW-shared spins 24307, rounds 729240, OS waits 24278 
RW-excl spins 16, rounds 1680, OS waits 56 
Spin rounds per wait: 29.98 mutex, 30.00 RW-shared, 105.00 RW-excl 
------------ 
TRANSACTIONS 
------------ 
Trx id counter 712274 
Purge done for trx's n:o < 712178 undo n:o < 0 state: running but idle 
History list length 1593 
LIST OF TRANSACTIONS FOR EACH SESSION: 
---TRANSACTION 0, not started 
MySQL thread id 18286, OS thread handle 0x2b9cf470f700, query id 2307113 bb116-14-164-108.singnet.com.sg 116.14.164.108 meclub2359 init 
show engine innodb status 
---TRANSACTION 0, not started 
MySQL thread id 18285, OS thread handle 0x2b9cf4444700, query id 2306954 bb116-14-164-108.singnet.com.sg 116.14.164.108 meclub2359 cleaning up 
---TRANSACTION 712266, not started 
MySQL thread id 18270, OS thread handle 0x2b9cf43c2700, query id 2307088 172.31.8.174 meclub2359 cleaning up 
---TRANSACTION 712235, not started 
MySQL thread id 18268, OS thread handle 0x2b9cf3896700, query id 2306757 172.31.8.174 meclub2359 cleaning up 
---TRANSACTION 712268, not started 
MySQL thread id 18267, OS thread handle 0x2b9cf4381700, query id 2307091 172.31.8.174 meclub2359 cleaning up 
---TRANSACTION 712272, not started 
MySQL thread id 5214, OS thread handle 0x2b9cf31dd700, query id 2307112 localhost 127.0.0.1 rdsadmin cleaning up 
---TRANSACTION 712269, ACTIVE 31 sec starting index read 
mysql tables in use 1, locked 1 
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s) 
MySQL thread id 18288, OS thread handle 0x2b9cf44c6700, query id 2307092 172.31.8.174 meclub2359 updating 
UPDATE stardate SET winnersSelected=1 WHERE id='6' 
------- TRX HAS BEEN WAITING 31 SEC FOR THIS LOCK TO BE GRANTED: 
RECORD LOCKS space id 4067 page no 3 n bits 72 index `PRIMARY` of table `ebdb`.`stardate` trx id 712269 lock_mode X locks rec but not gap waiting 
Record lock, heap no 3 PHYSICAL RECORD: n_fields 16; compact format; info bits 0 
0: len 4; hex 00000006; asc  ;; 
1: len 6; hex 0000000addcd; asc  ;; 
2: len 7; hex 180000021d2d57; asc  -W;; 
3: len 30; hex 68747470733a2f2f73332d61702d736f757468656173742d312e616d617a; asc https://s3-ap-southeast-1.amaz; (total 62 bytes); 
4: len 30; hex 4d75736963616c204576656e696e67207769746820456c6c696520476f75; asc Musical Evening with Ellie Gou; (total 35 bytes); 
5: len 30; hex 4d75736963616c204576656e696e67207769746820456c6c696520476f75; asc Musical Evening with Ellie Gou; (total 35 bytes); 
6: len 30; hex 4d75736963616c204576656e696e67207769746820456c6c696520476f75; asc Musical Evening with Ellie Gou; (total 255 bytes); 
7: len 22; hex 53696e6761706f72650d0a4d6172696e612042617920; asc Singapore Marina Bay ;; 
8: len 20; hex 52443230313530394d434d4543444153434d5346; asc RD201509MCMECDASCMSF;; 
9: len 4; hex 80000002; asc  ;; 
10: len 5; hex 9997295000; asc )P ;; 
11: len 5; hex 999702a000; asc  ;; 
12: len 4; hex 8000000c; asc  ;; 
13: len 1; hex 81; asc ;; 
14: len 5; hex 999706e345; asc  E;; 
15: len 5; hex 99972ee820; asc . ;; 

------------------ 
---TRANSACTION 712213, ACTIVE 501 sec 
5 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 3 
MySQL thread id 18284, OS thread handle 0x2b9cf3daa700, query id 2307007 172.31.8.174 meclub2359 cleaning up 
Trx read view will not see trx with id >= 712249, sees < 712141 
---TRANSACTION 712197, ACTIVE 574 sec 
5 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 3 
MySQL thread id 18283, OS thread handle 0x2b9cf4403700, query id 2306959 172.31.8.174 meclub2359 cleaning up 
Trx read view will not see trx with id >= 712241, sees < 712141 
---TRANSACTION 712184, ACTIVE 595 sec 
5 lock struct(s), heap size 1184, 1 row lock(s), undo log entries 3 
MySQL thread id 18281, OS thread handle 0x2b9cf468d700, query id 2306856 172.31.8.174 meclub2359 cleaning up 
Trx read view will not see trx with id >= 712240, sees < 712141 
---TRANSACTION 712141, ACTIVE 935 sec 
7 lock struct(s), heap size 1184, 12 row lock(s), undo log entries 19 
MySQL thread id 18279, OS thread handle 0x2b9cf4485700, query id 2306383 172.31.8.174 meclub2359 cleaning up 
Trx read view will not see trx with id >= 712146, sees < 712146 
-------- 
FILE I/O 
-------- 
I/O thread 0 state: waiting for completed aio requests (insert buffer thread) 
I/O thread 1 state: waiting for completed aio requests (log thread) 
I/O thread 2 state: waiting for completed aio requests (read thread) 
I/O thread 3 state: waiting for completed aio requests (read thread) 
I/O thread 4 state: waiting for completed aio requests (read thread) 
I/O thread 5 state: waiting for completed aio requests (read thread) 
I/O thread 6 state: waiting for completed aio requests (write thread) 
I/O thread 7 state: waiting for completed aio requests (write thread) 
I/O thread 8 state: waiting for completed aio requests (write thread) 
I/O thread 9 state: waiting for completed aio requests (write thread) 
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] , 
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0 
Pending flushes (fsync) log: 0; buffer pool: 0 
562 OS file reads, 295536 OS file writes, 202242 OS fsyncs 
0.00 reads/s, 0 avg bytes/read, 0.24 writes/s, 0.18 fsyncs/s 
------------------------------------- 
INSERT BUFFER AND ADAPTIVE HASH INDEX 
------------------------------------- 
Ibuf: size 1, free list len 0, seg size 2, 0 merges 
merged operations: 
insert 0, delete mark 0, delete 0 
discarded operations: 
insert 0, delete mark 0, delete 0 
Hash table size 1241027, node heap has 2 buffer(s) 
0.06 hash searches/s, 0.27 non-hash searches/s 
--- 
LOG 
--- 
Log sequence number 87135734 
Log flushed up to 87135734 
Pages flushed up to 87135734 
Last checkpoint at 87135734 
0 pending log writes, 0 pending chkp writes 
133514 log i/o's done, 0.09 log i/o's/second 
---------------------- 
BUFFER POOL AND MEMORY 
---------------------- 
Total memory allocated 641744896; in additional pool allocated 0 
Dictionary memory allocated 264646 
Buffer pool size 38271 
Free buffers  20250 
Database pages  18019 
Old database pages 6631 
Modified db pages 0 
Pending reads 0 
Pending writes: LRU 0, flush list 0, single page 0 
Pages made young 423, not young 82 
0.00 youngs/s, 0.00 non-youngs/s 
Pages read 521, created 17502, written 131006 
0.00 reads/s, 0.00 creates/s, 0.12 writes/s 
Buffer pool hit rate 1000/1000, young-making rate 0/1000 not 0/1000 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s 
LRU len: 18019, unzip_LRU len: 0 
I/O sum[4]:cur[0], unzip sum[0]:cur[0] 
-------------- 
ROW OPERATIONS 
-------------- 
0 queries inside InnoDB, 0 queries in queue 
4 read views open inside InnoDB 
Main thread process no. 14465, id 47953069967104, state: sleeping 
Number of rows inserted 55739, updated 14635, deleted 309, read 1463461 
0.00 inserts/s, 0.03 updates/s, 0.00 deletes/s, 35.00 reads/s 
---------------------------- 
END OF INNODB MONITOR OUTPUT 
============================ 

它看起來好像有一些疑問掛？的show processlist

如果讓我怎麼調試更加凡在我的應用程序會導致這個輸出？我正在使用AWS RDS，Elastic Beanstalk，NodeJS/SailsJS。

UPDATE

我注意到這個問題只發生在一排。當我嘗試UPDATE stardate SET winnersSelected=1 WHERE id='6'。

UPDATE

我發現，在代碼的改變關閉連接工程。但仍然好奇，我怎麼從上面的輸出中看出原因是什麼？我認爲這會很有用。我不確定這是否是原因。

例如，我看到

---TRANSACTION 0, not started 
MySQL thread id 18285, OS thread handle 0x2b9cf4444700, query id 2306954 bb116-14-164-108.singnet.com.sg 116.14.164.108 meclub2359 cleaning up 

---TRANSACTION 712235, not started 
MySQL thread id 18268, OS thread handle 0x2b9cf3896700, query id 2306757 172.31.8.174 meclub2359 cleaning up 

爲什麼它似乎像清理走這麼長時間？我應該擔心嗎？

---TRANSACTION 712269, ACTIVE 31 sec starting index read 
mysql tables in use 1, locked 1 
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s) 
MySQL thread id 18288, OS thread handle 0x2b9cf44c6700, query id 2307092 172.31.8.174 meclub2359 updating 
UPDATE stardate SET winnersSelected=1 WHERE id='6' 
------- TRX HAS BEEN WAITING 31 SEC FOR THIS LOCK TO BE GRANTED: 
RECORD LOCKS space id 4067 page no 3 n bits 72 index `PRIMARY` of table `ebdb`.`stardate` trx id 712269 lock_mode X locks rec but not gap waiting 
Record lock, heap no 3 PHYSICAL RECORD: n_fields 16; compact format; info bits 0 
0: len 4; hex 00000006; asc  ;; 
1: len 6; hex 0000000addcd; asc  ;; 
2: len 7; hex 180000021d2d57; asc  -W;; 
3: len 30; hex 68747470733a2f2f73332d61702d736f757468656173742d312e616d617a; asc https://s3-ap-southeast-1.amaz; (total 62 bytes); 
4: len 30; hex 4d75736963616c204576656e696e67207769746820456c6c696520476f75; asc Musical Evening with Ellie Gou; (total 35 bytes); 
5: len 30; hex 4d75736963616c204576656e696e67207769746820456c6c696520476f75; asc Musical Evening with Ellie Gou; (total 35 bytes); 
6: len 30; hex 4d75736963616c204576656e696e67207769746820456c6c696520476f75; asc Musical Evening with Ellie Gou; (total 255 bytes); 
7: len 22; hex 53696e6761706f72650d0a4d6172696e612042617920; asc Singapore Marina Bay ;; 
8: len 20; hex 52443230313530394d434d4543444153434d5346; asc RD201509MCMECDASCMSF;; 
9: len 4; hex 80000002; asc  ;; 
10: len 5; hex 9997295000; asc )P ;; 
11: len 5; hex 999702a000; asc  ;; 
12: len 4; hex 8000000c; asc  ;; 
13: len 1; hex 81; asc ;; 
14: len 5; hex 999706e345; asc  E;; 
15: len 5; hex 99972ee820; asc . ;; 

我可以從上面的輸出說，查詢UPDATE stardate SET winnersSelected=1 WHERE id='6'被阻止？但是我怎麼能說出來？

Answer 1

當處理困難的MySQL診斷問題時，通常你必須求助於gdb。你可以做這樣的事情：

gdb -ex "set pagination 0" -ex "thread apply all bt" \ 
    --batch -p $(pidof mysqld) 

然後你挖通過堆棧跟蹤的列表，並與源的知識一點點你能弄清楚到底是怎麼回事。

長時間「清理」的可能原因是某處被另一個線程佔用的某個關鍵鎖，並且可能有多種原因。如果你粘貼堆棧跟蹤，我將能夠讓你知道發生了什麼。

InnoDB中的死鎖實際上是一種合法的情況。它的設計方式是，在某些情況下，鎖定算法發現自己​​死鎖，但很少見。該問題通過鎖定等待超時進行緩解 - 達到時，會中止事務以避免死鎖。理論上講，應該編寫理想的InnoDB客戶端代碼，以在所有事務由於死鎖而失敗時重試所有事務。在實踐中，重構一個龐大的代碼庫以符合這個原則可能非常困難，但我仍然建議選擇一些關鍵的戰鬥並重構最麻煩的代碼以符合。

爲避免死鎖，請經常提交您的事務，並避免以不可預知的順序更新記錄。當然，這將包括適當的連接清理 - 正如你在案例中所觀察到的那樣。如果不關閉連接，你可以有一個看似天真的情景是這樣的：

• BEGIN
• 選擇
• 沒有活動時間長

的問題是，該交易使用SELECT鎖定已讀取的行，並且不會解鎖它們，直到COMMIT/ROLLBACK。

如果您有很多難以清理的混亂代碼，您可能需要考慮放棄使用連接池。 MySQL具有非常低的會話啓動開銷，並且可以很好地處理頻繁的重新連接。這種非活動連接可能會在應用程序請求自動終止時關閉（我假定有些代碼在大量應用程序中常見），並且您將不會與正在返回到在該狀態下的連接池。

Answer 2

如果事務由於死鎖而失敗，請始終準備重新發出事務。僵局並不危險。再試一次。我會嘗試並捕獲該異常

https://dev.mysql.com/doc/refman/5.0/en/innodb-deadlocks.html