【工作筆記】SQL Timeout追蹤

幾個禮拜前去客戶那處理『SQL效能問題』，到場後，問題延伸為『SQL不定期發生Timeout的問題』

【客戶問題描述】
AP會建立100多個連線，且同時會將程式用幾十個連線來並行處理事務，會在不固定的時間會發生SQL Timeout的問題，由程式端無法定位是哪句SQL以及哪支程式導致的問題，在DB端也不會看到任何的錯誤訊息及警告訊息出現在Error Log中 

【架構背景】
OS: CentOS 6.8, CPU 20 Cores, RAM 64G, HDD RAID 10
DB: MariaDB 10.0.1 Galera Cluster

【問題追踨】

1. 在執行壓測過程中監控作業系統的狀態，包括CPU、RAM、IO的負載狀況
   =>監控的結果CPU的load average大約在1，RAM有使用到少量的SWAP，cached的部份還有滿多可以使用，IO的負載不算太高，整體看來應該不是硬體方面造成的問題
2. 在執行壓測過程中監控資料庫的錯誤日誌、慢查詢記錄、show processlist的狀況
   =>錯誤日誌並未記錄到任何的錯誤及警告訊息，慢查詢只有其他資料庫中全表掃描的記錄，show processlist看到多數的連線均為sleep狀態，且SQL執行的時間都很短
3. 在執行壓測過程中監控InnoDB的狀態
   

   ------------------------
   LATEST DETECTED DEADLOCK
   ------------------------
   2017-01-17 16:02:22 7fd7a00e6700
   *** (1) TRANSACTION:
   TRANSACTION 755310052, ACTIVE 2 sec fetching rows
   mysql tables in use 1, locked 1
   LOCK WAIT 6 lock struct(s), heap size 1184, 154 row lock(s)
   MySQL thread id 2916595, OS thread handle 0x7fdd2d9fe700, query id 213093063 192.168.3.2 tsap Sending data
   SELECT id, cid, time, retry FROM ss WHERE rs = 0 AND time < '2017-01-17 16:02:25' LIMIT 100 FOR UPDATE
   *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
   RECORD LOCKS space id 65 page no 652 n bits 232 index `PRIMARY` of table `ts`.`ss` trx table locks 1 total table locks 5  trx id 755310052 lock_mode X locks rec but not gap waiting lock hold time 0 wait time before grant 0 
   *** (2) TRANSACTION:
   TRANSACTION 755311633, ACTIVE 1 sec fetching rows, thread declared inside InnoDB 2915
   mysql tables in use 1, locked 1
   32 lock struct(s), heap size 6544, 3131 row lock(s)
   MySQL thread id 2907926, OS thread handle 0x7fd7a00e6700, query id 213099909 192.168.3.1 tsap updating
   delete from ss where userId = 337263
   *** (2) HOLDS THE LOCK(S):
   RECORD LOCKS space id 65 page no 652 n bits 232 index `PRIMARY` of table `ts`.`ss` trx table locks 5 total table locks 5  trx id 755311633 lock_mode X lock hold time 1 wait time before grant 0 
   *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
   RECORD LOCKS space id 65 page no 448 n bits 264 index `PRIMARY` of table `ts`.`ss` trx table locks 5 total table locks 5  trx id 755311633 lock_mode X waiting lock hold time 0 wait time before grant 0 
   *** WE ROLL BACK TRANSACTION (1) 

   
   =>有出現Dead Lock的狀況，但客戶說那個問題他們已有修改程式，叫我先忽略
4. 最後沒辦法，只好開啟General Log來追踨
   =>能抓到timeout發生時的SQL，但同時執行的SQL太多，也無法定位是哪句語法造成的。
5. Performance Schema沒有啟用，因此無法直接透過P_S來抓Lock的內容
   =>最後只能從Information Schema中的INNODB_LOCKS看到有大量Lock的SQL，但很快的就消失

   MariaDB [information_schema]> select * from INNODB_TRX;
   +-----------+-----------+---+----------------------------------------------------------------------------------------------------------+
   | trx_id    | trx_state |...| trx_query                                                                                                |
   +-----------+-----------+---+----------------------------------------------------------------------------------------------------------+
   | 739668042 | LOCK WAIT |...| select a, b from ss where cid='12334555' and rs = 1 lock in share mode                                   |
   | 739667985 | LOCK WAIT |...| ......                                                                                                   |
   | 739667947 | LOCK WAIT |...| SELECT id, cid, rs, retry_seq FROM ss WHERE rs = 0 AND time < '2017-01-17 12:23:25' LIMIT 100 FOR UPDATE |
   +-----------+-----------+---+----------------------------------------------------------------------------------------------------------+
   41 rows in set (0.00 sec)
   

【問題分析】

從INNODB_TRX表中所抓到的內容發現，他在語法中加入了2個顯式鎖：FOR UPDATE和LOCK IN SHARE MODE，前者是排他鎖，後者是共享鎖 ，這2種鎖是有衝突的，也就是說如果有使用到同一行或同範圍中的資料則會發生鎖等待的狀況。

在InnoDB中預設的隔離級別為Repeatable-Read(RR)，在此隔離級別下FOR UPDATE會發生Gap Lock，即會鎖定資料的前後範圍的資料。
在這句語法中：

SELECT ... WHERE ... time < '2017-01-17 12:23:25' FOR UPDATE

有幾個問題：

1. 雖然time有建索引，但它是屬於範圍查詢，基本上也用不到索引且查詢範圍資料大於全表資料的30%，會被優化器歸屬於全表掃描，若有鎖的情況則會擴大範圍變全表鎖
2. Gap Lock會鎖定資料的前後範圍的資料，如前項說明，基本上鎖的範圍也是全表鎖定

如果有很快執行commit，則不會發生太長時間等待鎖定，但他們的程式執行順序如下圖：

每個APP的交易都是執行一連串的SQL指令，最後才會進行commit的動作

也就是說，當APP_1執行SELECT ... FOR UPDATE進行鎖表後，其他APP執行SELECT時都必須等待APP_1解除鎖定才能繼續執行。

另外，在問題分析的過程中，客戶才發現在他們的程式中有指定，若SQL查詢超過5秒則視為Timeout，會將所有指令取消做RollBack動作

這也是為什麼在INNODB_TRX表、INNODB_LOCKS表及INNODB_LOCK_WAITS表中都沒辦法看到等待超過5秒的指令。

最後請客戶將SQL語法執行的順序調整後，再無出現Timeout的問題

【總結】

1. SELECT ... FOR UPDATE的語法通常都是為了要更新前抓取到最新資料所設的，建議有這種排他鎖的指令最好能盡快的做commit動作。
2. 除了FOR UPDATE之外，其餘顯式鎖定的指令避免包在大的transaction中執行，盡可能的縮短處理時間避免長時間鎖定
3. 可將預設的innodb_lock_wait_timout由10秒縮短，避免在高壓力情況下發生長時間等待造成負載過高