【工作筆記】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的狀態
    1. ------------------------
    2. LATEST DETECTED DEADLOCK
    3. ------------------------
    4. 2017-01-17 16:02:22 7fd7a00e6700
    5. *** (1) TRANSACTION:
    6. TRANSACTION 755310052, ACTIVE 2 sec fetching rows
    7. mysql tables in use 1, locked 1
    8. LOCK WAIT 6 lock struct(s), heap size 1184, 154 row lock(s)
    9. MySQL thread id 2916595, OS thread handle 0x7fdd2d9fe700, query id 213093063 192.168.3.2 tsap Sending data
    10. SELECT id, cid, time, retry FROM ss WHERE rs = 0 AND time < '2017-01-17 16:02:25' LIMIT 100 FOR UPDATE
    11. *** (1) WAITING FOR THIS LOCK TO BE GRANTED:
    12. 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 
    13. *** (2) TRANSACTION:
    14. TRANSACTION 755311633, ACTIVE 1 sec fetching rows, thread declared inside InnoDB 2915
    15. mysql tables in use 1, locked 1
    16. 32 lock struct(s), heap size 6544, 3131 row lock(s)
    17. MySQL thread id 2907926, OS thread handle 0x7fd7a00e6700, query id 213099909 192.168.3.1 tsap updating
    18. delete from ss where userId = 337263
    19. *** (2) HOLDS THE LOCK(S):
    20. 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 
    21. *** (2) WAITING FOR THIS LOCK TO BE GRANTED:
    22. 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 
    23. *** 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，但很快的就消失 
    1. MariaDB [information_schema]> select * from INNODB_TRX;
    2. +-----------+-----------+---+----------------------------------------------------------------------------------------------------------+
    3. | trx_id    | trx_state |...| trx_query                                                                                                |
    4. +-----------+-----------+---+----------------------------------------------------------------------------------------------------------+
    5. | 739668042 | LOCK WAIT |...| select a, b from ss where cid='12334555' and rs = 1 lock in share mode                                   |
    6. | 739667985 | LOCK WAIT |...| ......                                                                                                   |
    7. | 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 |
    8. +-----------+-----------+---+----------------------------------------------------------------------------------------------------------+
    9. 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，即會鎖定資料的前後範圍的資料。
在這句語法中：
  1. 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秒縮短，避免在高壓力情況下發生長時間等待造成負載過高


留言

張貼留言

這個網誌中的熱門文章

MySQL監控軟體MEM及PMM介紹

圖片
MySQL監控軟體： PMP(Percona Monitoring Plugin) ：Percona之前的監控是以Plugin或Template的方式加載到其他的監控軟體上，他有支援Zabbix、Nagios和Cacti等3個常用的監控軟體，詳細的介紹可以參考官網： Percona Monitoring Plugins MEM(MySQL Enterprise Monitor) ：官方提供的監控軟體，需購企業版才能使用此功能，可以監控DB內的狀況和InnoDB、NDB、Replication等的內容，另外還可以監控作業系統上的部份內容，例如硬碟、CPU、RAM、網路…等使用狀況，除了監控之外，還有Query Analyzer及發送告警功能，詳細的介紹參考官網： MySQL Enterprise Monitor PMM(Percona Monitoring and Management) ：它是一個用於管理及監控MySQL及MongoDB效能的開源平台，它提供了對MyISAM、InnoDB、TokuDB和PXC/Glarera的監控，另外也提供了與MEM類似的Query Analytics的功能，可以檢視執行了哪些SQL指令，並對執行效能較差的語法進行優化；針對作業系統的部份也提供了硬碟、網路、CPU和RAM的監控，特別的是它提供了Context switches、Processes和interrupts的監控，Context Switches可以看到CPU上下切換文的狀況，Processes可以方便了解系統有多少程序在等待I/O，這3個是MEM沒有提供的。詳細內容參考官方： Percona Monitoring and Management 架構說明： MEM架構 MEM是由Java+Apache Tomcat+MySQL組成的監控軟體 主要安裝Service Manager(也可稱Monitor Server)它有內建一個Agent可以讓你遠端監控 或者是另外在MySQL Server上安裝Agent軟體，其差別在於能否搜集作業系統上的資訊，裝了Agent才能在作業系統上搜集資訊 而DB端的資訊會透過本機或Service Manager的Agent，連到DB裡的Performance Schema中搜集資訊，再儲存到Servi...
閱讀完整內容

MySQL Router 設定檔說明

設定檔範例： 　 　 　 [DEFAULT] logging_folder  = /opt/mysql-router/log plugin_folder   = /opt/mysql-router/lib/mysqlrouter runtime_folder  = /opt/mysql-router/run config_folder   = /opt/mysql-router [logger] level = INFO ## these section are only for standalone [routing:read_write] bind_address    = 192.168.56.107 bind_port       = 7001 destinations    = 192.168.56.102:3306,192.168.56.102:3307 mode            = read-write connect_timeout    = 5 max_connections   = 100 [routing:read_only] bind_address    = 192.168.56.107 bind_port       = 7002 destinations    = 192.168.56.102:3308,192.168.56.102:3309 mode            = read-only connect_timeout    = 1 max_connections   = 100 ## these section are used for Fabric [fabric_cache:my_fabric] address    = 192.168.56.101 user   ...
閱讀完整內容