作者：xuty
本文來源：原創投稿
*愛可生開源社區出品，原創內容未經授權不得隨意使用，轉載請聯系小編并注明來源。
一、背景
#### 20191219 10:10:10,234 | com.alibaba.druid.filter.logging.Log4jFilter.statementLogError(Log4jFilter.java:152) | ERROR | {conn-10593, pstmt-38675} execute error. update operation_service set offlinemark=? , resourcestatus=? where RowGuid=?com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Lock wait timeout exceeded; try restarting transaction上述這個錯誤，接觸 MySQL 的同學或多或少應該都遇到過，專業一點來說，這個報錯我們稱之為鎖等待超時。
根據鎖的類型主要細分為：
本文僅介紹如何有效解決行鎖等待超時，因為大多數項目都是此類錯誤，元數據鎖等待超時則不涉及講解。
二、行鎖的等待
在介紹如何解決行鎖等待問題前，先簡單介紹下這類問題產生的原因。
產生原因簡述：當多個事務同時去操作（增刪改）某一行數據的時候，MySQL 為了維護 ACID 特性，就會用鎖的形式來防止多個事務同時操作某一行數據，避免數據不一致。只有分配到行鎖的事務才有權力操作該數據行，直到該事務結束，才釋放行鎖，而其他沒有分配到行鎖的事務就會產生行鎖等待。如果等待時間超過了配置值（也就是 innodb_lock_wait_timeout 參數的值，個人習慣配置成 5s，MySQL 官方默認為 50s），則會拋出行鎖等待超時錯誤。
如上圖所示，事務 A 與事務 B 同時會去 Insert 一條主鍵值為 1 的數據，由于事務 A 首先獲取了主鍵值為 1 的行鎖，導致事務 B 因無法獲取行鎖而產生等待，等到事務 A 提交后，事務 B 才獲取該行鎖，完成提交。
這里強調的是行鎖的概念，雖然事務 B 重復插入了主鍵，但是在獲取行鎖之前，事務一直是處于行鎖等待的狀態，只有獲取行鎖后，才會報主鍵沖突的錯誤。
當然這種 Insert 行鎖沖突的問題比較少見，只有在大量并發插入場景下才會出現，項目上真正常見的是 update&delete 之間行鎖等待，這里只是用于示例，原理都是相同的。
三、產生的原因
根據我之前接觸到的此類問題，大致可以分為以下幾種原因：
1. 程序中非數據庫交互操作導致事務掛起
將接口調用或者文件操作等這一類非數據庫交互操作嵌入在 SQL 事務代碼之中，那么整個事務很有可能因此掛起（接口不通等待超時或是上傳下載大附件）。
2. 事務中包含性能較差的查詢 SQL
事務中存在慢查詢，導致同一個事務中的其他 DML 無法及時釋放占用的行鎖，引起行鎖等待。
3. 單個事務中包含大量 SQL
通常是由于在事務代碼中加入 for 循環導致，雖然單個 SQL 運行很快，但是 SQL 數量一大，事務就會很慢。
4. 級聯更新 SQL 執行時間較久
這類 SQL 容易讓人產生錯覺，例如：update A set ... where ...in (select B) 這類級聯更新，不僅會占用 A 表上的行鎖，也會占用 B 表上的行鎖，當 SQL 執行較久時，很容易引起 B 表上的行鎖等待。
5. 磁盤問題導致的事務掛起
極少出現的情形，比如存儲突然離線，SQL 執行會卡在內核調用磁盤的步驟上，一直等待，事務無法提交。
綜上可以看出，如果事務長時間未提交，且事務中包含了 DML 操作，那么就有可能產生行鎖等待，引起報錯。
四、定位難點
當 web 日志中出現行鎖超時錯誤后，很多開發都會找我來排查問題，這里說下問題定位的難點！
1. MySQL 本身不會主動記錄行鎖等待的相關信息，所以無法有效的進行事后分析。
2. 鎖爭用原因有多種，很難在事后判斷到底是哪一類問題場景，尤其是事后無法復現問題的時候。
3. 找到問題 SQL 后，開發無法有效從代碼中挖掘出完整的事務，這也和公司框架-產品-項目的架構有關，需要靠 DBA 事后采集完整的事務 SQL 才可以進行分析。
五、常用方法
先介紹下個人通常是如何解決此類問題的， 這里問題解決的前提是問題可以復現，只要不是突然出現一次，之后再也不出現，一般都是可以找到問題源頭的。
這里問題復現分為兩種情景：
1. 手動復現
只要按照一定的操作，就可以復現報錯，這種場景較簡單！
2. 隨機復現
不知道何時會突然報錯，無法手動復現，這種場景較難！
下面先寫下統一的模擬場景，用于復現行鎖超時問題，便于大家理解：
--表結構CREATE TABLE `emp` ( `id` int(11) NOT NULL, KEY `idx_id` (`id`)) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4從1~100w插入100w行記錄。--測試過程：事務1：start transaction;delete from emp where id=1;select * from emp where id in (select id from emp); -->模擬慢查詢，執行時間很久，事務因此一直不提交，行鎖也不釋放.commit;事務2：start transaction;delete from emp where id < 10; --> 處于等待id=1的行鎖狀態，當達到行鎖超時時間（這里我配置了超時時間為 5s）后，返回行鎖超時報錯rollback;5.1 手動復現場景
這個場景通常只需要通過 innodb 行鎖等待腳本就可以知道當前 MySQL 的 innodb 行鎖等待情況，例如我們一邊模擬上述報錯場景（模擬頁面操作），另一邊使用腳本查詢（需要在超時之前查詢，否則超時報錯后就看不到了）。
/*innodb 行鎖等待腳本*/SELECT r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query,concat(timestampdiff(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP()),'s') AS duration,b.trx_mysql_thread_id blocking_thread,t.processlist_command state,b.trx_query blocking_current_query,e.sql_text blocking_last_queryFROM information_schema.innodb_lock_waits wJOIN information_schema.innodb_trx b ON b.trx_id=w.blocking_trx_idJOIN information_schema.innodb_trx r ON r.trx_id=w.requesting_trx_idJOIN performance_schema.threads t on t.processlist_id=b.trx_mysql_thread_idJOIN performance_schema.events_statements_current e USING(thread_id)如上我們可以看到事務 2 的線程 id 為 76，已經被事務 1，也就是線程 id 為 75 的事務阻塞了 3s，并且可以看到事務 1 當前執行的 SQL 為一個 SELECT。這里也解釋了很多開發經常問我的，為什么 SELECT 也會阻塞其他會話？
如果遇到這種情況，那么處理其實非常簡單。需要優化這個 SELECT 就好了，實在優化不了，把這個查詢扔到事務外就可以了，甚至都不需要挖掘出整個事務。
上述這個問題模擬，其實就是對應第三節問題產生原因中的第二點（事務中包含性能較差的查詢 SQL），下面我們把第一點（程序中非數據庫交互操作導致事務掛起）也模擬下，對比下現象。
我們只需要將事務 1 的過程改成如下即可。
事務1：start transaction;delete from emp where id=1;select * from emp where id in (select id from emp);等待60s(什么都不要做) --> 模擬接口調用超時，事務夯住，隨后再執行commit。commit;再次用腳本查看，可以看到現象是有所不同的，不同點在于，阻塞事務處于 sleep 狀態，即事務當前并不在跑 SQL。從 DBA 的角度看，這類現象八成就可以斷定是代碼在事務中嵌入了其他的交互操作導致的事務掛起（另外也有可能是網絡問題導致的事務僵死），因為程序并不像人，它不會偷懶，不會出現事務執行到一半，休息一會再提交一說。
如果是這類現象的問題，因為本質并不是由于 SQL 慢導致的事務掛起，所以必須要到代碼里去找到對應的點，看下到底是在做什么交互操作卡住了。
這里就需要開發去排查代碼才可以找到源頭，但是唯一可用的信息就是該事務最后執行的一條 SQL，也就是上圖中最后一列，從我之前的經驗來看（絕大時候），開發很難單從這一條 SQL 就可以找到代碼里具體位置，尤其是當這條 SQL 是一條很常見的 SQL，就更為困難！
當面對這種情況，就需要 DBA 去挖掘出這個事務執行過的所有 SQL，然后再讓開發去排查代碼，這樣難度應該就小多了。這里就需要用到 MySQL 的 general_log，該日志用于記錄 MySQL 中所有運行過的 SQL。
--查看general_log是否開啟，及文件名mysql> show variables like '%general_log%';+------------------+--------------------------------------+| Variable_name | Value |+------------------+--------------------------------------+| general_log | OFF || general_log_file | /data/mysql_data/192-168-188-155.log |+------------------+--------------------------------------+--暫時開啟general_logmysql> set global general_log=1;Query OK, 0 rows affected (0.00 sec)--暫時關閉general_logmysql> set global general_log=0;Query OK, 0 rows affected (0.00 sec)開啟 general_log 后，手動復現的時候通過 innodb 行鎖等待腳本查詢結果中的線程 ID，去 general_log 找到對應的事務分析即可，如下：
根據線程 ID 可以很輕易的從 general_log 中找到對應時間點的事務操作（實際場景下可能需要通過管道命令過濾）。如上圖所示，事務 1 與事務 2 的全部 SQL 都可以找到，再通過這些 SQL 去代碼中找到對應的位置即可，比如上圖中線程 ID 為 111 的事務，執行 select * from emp where id in (select id from emp) 后到真正提交，過了 1min 左右，原因要么就是這條 SQL 查詢慢，要么就是代碼在執行其他交互操作。
PS：general_log 由于會記錄所有 SQL，所以對 MySQL 性能影響較大，且容易暴漲，所以只在問題排查時暫時開啟，問題排查后，請及時關閉！
5.2 隨機復現場景
相較于手動復現場景，這種場景因為具有隨機性，所以無法一邊模擬報錯，一邊通過腳本查詢到具體的阻塞情況，因此需要通過其他方式來監控 MySQL 的阻塞情況。
我一般是通過在 Linux 上后臺跑監控腳本（innodb_lock_monitor.sh）來記錄 MySQL 阻塞情況，腳本如下：
#!/bin/bash#賬號、密碼、監控日志user="root"password="Gepoint"logfile="/root/innodb_lock_monitor.log"while truedo num=`mysql -u${user} -p${password} -e "select count(*) from information_schema.innodb_lock_waits" |grep -v count` if [[ $num -gt 0 ]];then date >> /root/innodb_lock_monitor.log mysql -u${user} -p${password} -e "SELECT r.trx_mysql_thread_id waiting_thread,r.trx_query waiting_query, \concat(timestampdiff(SECOND,r.trx_wait_started,CURRENT_TIMESTAMP()),'s') AS duration,\b.trx_mysql_thread_id blocking_thread,t.processlist_command state,b.trx_query blocking_query,e.sql_text \FROM information_schema.innodb_lock_waits w \JOIN information_schema.innodb_trx b ON b.trx_id=w.blocking_trx_id \JOIN information_schema.innodb_trx r ON r.trx_id=w.requesting_trx_id \JOIN performance_schema.threads t on t.processlist_id=b.trx_mysql_thread_id \JOIN performance_schema.events_statements_current e USING(thread_id) \G " >> ${logfile} fi sleep 5done再次查看
--使用 nohup 命令后臺運行監控腳本[root@192-168-188-155 ~]# nohup sh innodb_lock_monitor.sh &[2] 31464nohup: ignoring input and appending output to ‘nohup.out’--查看 nohup.out 是否出現報錯[root@192-168-188-155 ~]# tail -f nohup.outmysql: [Warning] Using a password on the command line interface can be insecure.mysql: [Warning] Using a password on the command line interface can be insecure.mysql: [Warning] Using a password on the command line interface can be insecure.--定時查看監控日志是否有輸出(沒有輸出的話，這個日志也不會生成哦！)[root@192-168-188-155 ~]# tail -f innodb_lock_monitor.logWed Feb 5 11:30:11 CST 2020*************************** 1. row *************************** waiting_thread: 112 waiting_query: delete from emp where id < 10 duration: 3sblocking_thread: 111 state: Sleep blocking_query: NULL sql_text: select * from emp where id in (select id from emp)當監控日志有輸出阻塞信息時，后續解決方案就和之前的手動復現場景一致。
PS：問題排查完成后，請及時關閉后臺監控進程，通過 kill+pid 的方式直接關閉即可！
六、Performance_Schema
之前的方法感覺不是很方便，因為 general_log 需要訪問服務器，且過濾分析也較難，需要一定的 MySQL 基礎及 Linux 基礎才適用，因此想尋找一種更為簡便的方法。
6.1 方法介紹
個人想法是利用 MySQL 5.5 開始提供的 performance_schema 性能引擎來進行分析，Performance_Schema 是 MySQL 提供的在系統底層監視 MySQL 服務器性能的一個特性，其提供了大量監控項，包括：鎖、IO、事務、內存使用等。
介紹下主要原理：
1. 主要用的表有 2 張 events_transactions_history_long 和 events_statements_history_long。
2. transactions_history_long 會記錄歷史事務信息，events_statements_history_long 則記錄歷史 SQL。
3. 從 transactions_history_long 中得到回滾事務的線程 ID，再根據時間范圍去篩選出可疑的事務，最后從 events_statements_history_long 得到事務對應的 SQL，從中排查哪個為源頭。
優點：
1. 不需要通過 general_log 來獲取事務 SQL。
2. 不需要監控腳本來獲取到行鎖等待情況。
3. 只需要訪問 MySQL 就可以實現，而不需要訪問服務器。
4. 性能開銷較小，且不會暴漲，因為是循環覆蓋寫入的。
5. 可以知道每條 SQL 的運行時長。
缺點：
1. history_long 相關表默認保留記錄有限，可能會把有用的數據刷掉，尤其是在 SQL 運行較多的系統。
2. 如果要加大 history_long 相關表的最大保留行數，需要重啟 MySQL，無法在線修改參數。
3. history_long 相關表記錄中的時間均為相對時間，也就是距離 MySQL 啟動的時長，看起來不是很方便。
4. history_long 相關表不會主動記錄行鎖等待的信息，所以只能通過先根據時間范圍篩選出可疑的事務，再進一步分析，不如腳本監控定位的準。
/*開啟performance_schema相關監控項，需要提前開啟performance_schema*/UPDATE performance_schema.setup_instruments SET ENABLED='YES', TIMED='YES' where name='transaction';UPDATE performance_schema.setup_consumers SET ENABLED='YES' where name like '%events_transactions%';UPDATE performance_schema.setup_consumers SET ENABLED='YES' where name like '%events_statements%';/*查看回滾事務SQL，確認是否是日志里報錯的事務*/SELECT a.THREAD_ID ,b.EVENT_ID ,a.EVENT_NAME ,CONCAT (b.TIMER_WAIT / 1000000000000,'s') AS trx_druation ,CONCAT (a.TIMER_WAIT / 1000000000000,'s') sql_druation ,a.SQL_TEXT,b.STATE,a.MESSAGE_TEXTFROM performance_schema.events_statements_history_long aJOIN performance_schema.events_transactions_history_long b ON a.THREAD_ID=b.THREAD_ID AND (a.NESTING_EVENT_ID=b.EVENT_ID OR a.EVENT_ID=b.NESTING_EVENT_ID)WHERE b.autocommit='NO' AND a.SQL_TEXT IS NOT NULL AND b.STATE='ROLLED BACK'/*查看該時間段內可疑事務即超過5s的事務SQL，這里默認innodb_lock_wait_timeout為5s*/SELECT a.THREAD_ID ,b.EVENT_ID ,a.EVENT_NAME ,CONCAT (b.TIMER_WAIT / 1000000000000,'s') AS trx_druation ,CONCAT (a.TIMER_WAIT / 1000000000000,'s') sql_druation ,a.SQL_TEXT,b.STATE,a.MESSAGE_TEXT,a.ROWS_AFFECTED,a.ROWS_EXAMINED,a.ROWS_SENTFROM performance_schema.events_statements_history_long aJOIN performance_schema.events_transactions_history_long b ON a.THREAD_ID=b.THREAD_ID AND (a.NESTING_EVENT_ID=b.EVENT_ID OR a.EVENT_ID=b.NESTING_EVENT_ID)WHERE b.autocommit='NO' AND SQL_TEXT IS NOT NULL AND b.STATE='COMMITTED' AND b.TIMER_WAIT / 1000000000000 > 5 AND b.TIMER_START < (SELECT TIMER_START FROM performance_schema.events_transactions_history_long WHERE THREAD_ID=70402 /*上述SQL查詢結果中的線程ID*/ AND EVENT_ID=518) /*上述SQL查詢結果中的事件ID*/ AND b.TIMER_END > ( SELECT TIMER_END FROM performance_schema.events_transactions_history_long WHERE THREAD_ID=70402 /*上述SQL查詢結果中的線程ID*/ AND EVENT_ID=518) /*上述SQL查詢結果中的事件ID*/ORDER BY a.THREAD_ID6.2 測試模擬
如果是用這種方法的話，那么就不需要分手動復現還是隨機復現了，操作方法都是一樣的，下面模擬下如何操作：
1. 首先通過上述方法開啟 performance_schema 相關監控項，會直接生效，無需重啟 MySQL。
2. 然后復現問題，這里最好是手動復現（因為復現后如果沒有及時查看，監控數據可能就會被刷掉），不行的話就只能等待隨機復現了。
3. 問題復現后通過上述腳本查詢是否存在回滾事務（即因為行鎖超時回滾的事務）。
4. 然后根據回滾事務的線程 ID 和事件 ID，帶入到最后一個腳本中，查看可疑事務，進行分析。
這里由于是測試環境模擬，所以結果非常了然，項目上實際輸出結果可能有很多，需要一一分析事務是否有問題！
七、總結
實際測試后，發現通過 performance_schema 來排查行鎖等待超時問題限制其實也比較多，而且最后的分析也是一門技術活，并不如一開始想象的那么簡單，有點事與愿違了。
通過 performance_schema 排查問題最難處理的有 3 點：
1. 時間問題，相對時間如何轉換為絕對時間，這個目前一直找不到好的方法。
2. 不會主動記錄下行所等待的信息，所以只能通過時間節點刷選后進一步分析。
3. 記錄被刷問題，因為是內存表，設置很大容易內存溢出，設置很小就容易被很快刷掉。
關于愛可生
愛可生成立于2003年，依托于融合、開放、創新的數據處理技術和服務能力，為大型行業用戶的特定場景提供深度挖掘數據價值的解決方案。
公司持續積累的核心關鍵技術，覆蓋到分布式數據庫集群、云數據平臺、數據庫大體量運管平臺、海量數據集成于存儲、清洗與治理、人工智能分析挖掘、可視化展現、安全與隱私保護等多個領域。
公司已與多個行業內的專業公司建立了長期伙伴關系，不斷促進新技術與行業知識相結合，為用戶尋求新的數據驅動的價值增長點。公司已在金融、能源電力、廣電、政府等行業取得了眾多大型用戶典型成功案例，獲得了市場的認可和業務的持續增長。
近期有測試反饋的問題有點多，其中關于系統可靠性測試提出的問題令人感到頭疼，一來這類問題有時候屬于“偶發”現象，難以在環境上快速復現；二來則是可靠性問題的定位鏈條有時候變得很長，極端情況下可能要從 A 服務追蹤到 Z 服務，或者是從應用代碼追溯到硬件層面。
本次分享的是一次關于 MySQL 高可用問題的定位過程，其中曲折頗多但問題本身卻比較有些代表性，遂將其記錄下來以供參考。
首先，本系統以 MySQL 作為主要的數據存儲部件。整一個是典型的微服務架構（SpringBoot + SpringCloud），持久層則采用了如下幾個組件：
在 MySQL 服務端部分，后端采用了雙主架構，前端以 keepalived 結合浮動IP（VIP）做一層高可用。如下：
說明
實際上，keepalived 和 MySQL 都實現了容器化，而 VIP 端口則映射到 VM 上的 nodePort 服務端口上。
Keepalived 是基于 VRRP 協議實現了路由層轉換的，在同一時刻，VIP 只會指向其中的一個虛擬機（master）。當主節點發生故障時，其他的人 keepalived 會檢測到問題并重新選舉出新的學生 master，此后 VIP 將切換到另一個可用的 MySQL 實例節點上。這樣一來，MySQL 數據庫就擁有了基礎的高可用能力。
另外一點，Keepalived 還會對 MySQL 實例進行定時的健康檢查，一旦發現 MySQL 實例不可用會將自身進程殺死，進而再觸發 VIP 的切換動作。
本次的測試用例也是基于虛擬機故障的場景來設計的：
持續以較小的壓力向業務服務發起訪問，隨后將其中一臺 MySQL 的容器實例(master)重啟。
按照原有的評估，業務可能會產生很小的抖動，但其中斷時間應該保持在秒級。然而經過多次的測試后發現，在重啟 MySQL 主節點容器之后，有一定的概率會出現業務卻再也無法訪問的情況！
在發生問題之后，開發同學的第一反應是 MySQL 高可用的機制出了問題。由于此前曾經出現過由于 keepalived 配置不當導致 VIP 未能及時切換的問題，因此對其已經有所戒備。
先是經過一通的排查，然后并沒有找到 keepalived 任何配置上的毛病都有。
然后在沒有辦法的情況下，重新測試了幾次，問題又復現了。
緊接著，我們提出了幾個疑點：
1.Keepalived 會根據 MySQL 實例的可達性進行判斷，會不會是健康檢查出了問題？
但在本次測試場景中，MySQL 容器銷毀會導致 keepalived 探測端口探測器產生失敗，這同樣會導致 keepalived 失效。如果 keepalived 也發生了中止，那么 VIP 應該能自動發生搶占。而通過對比兩臺虛擬機節點的信息后，發現 VIP 的確發生了切換。
2. 業務進程所在的容器是否發生了網絡不可達的問題？
嘗試進入容器，對當前發生切換后的浮動IP、端口執行 telnet 測試，發現仍然能訪問成功。
在排查前面兩個疑點之后，我們只能將目光轉向了業務服務的DB客戶端上。
從日志上看，在產生故障的時刻，業務側的確出現了一些異常，如下：
Unable to acquire JDBC Connection [n/a]
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:669) ~[HikariCP-2.7.9.jar!/:?]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:183) ~[HikariCP-2.7.9.jar!/:?]
...這里提示的是業務操作獲取連接超時了（超過了30秒）。那么，會不會是連接數不夠用呢？
業務接入采用的是 hikariCP 連接池，這也是市面上流行度很高的一款組件了。
我們隨即檢查了當前的連接池配置，如下：
//最小空閑連接數
spring.datasource.hikari.minimum-idle=10
//連接池最大大小
spring.datasource.hikari.maximum-pool-size=50
//連接最大空閑時長
spring.datasource.hikari.idle-timeout=60000
//連接生命時長
spring.datasource.hikari.max-lifetime=1800000
//獲取連接的超時時長
spring.datasource.hikari.connection-timeout=30000其中 注意到 hikari 連接池配置了 minimum-idle=10，也就是說，就算在沒有任何業務的情況下，連接池也應該保證有 10 個連接。更何況當前的業務訪問量極低，不應該存在連接數不夠使用的情況。
除此之外，另外一種可能性則可能是出現了“僵尸連接”，也就是說在重啟的過程中，連接池一直沒有釋放這些不可用的連接，最終造成沒有可用連接的結果。
開發同學對"僵尸鏈接"的說法深信不疑，傾向性的認為這很可能是來自于 HikariCP 組件的某個 BUG…
于是開始走讀 HikariCP 的源碼，發現應用層向連接池請求連接的一處代碼如下：
public class HikariPool{
//獲取連接對象入口
public Connection getConnection(final long hardTimeout) throws SQLException
{
suspendResumeLock.acquire();
final long startTime=currentTime();
try {
//使用預設的30s 超時時間
long timeout=hardTimeout;
do {
//進入循環，在指定時間內獲取可用連接
//從 connectionBag 中獲取連接
PoolEntry poolEntry=connectionBag.borrow(timeout, MILLISECONDS);
if (poolEntry==null) {
break; // We timed out... break and throw exception
}
final long now=currentTime();
//連接對象被標記清除或不滿足存活條件時，關閉該連接
if (poolEntry.isMarkedEvicted() || (elapsedMillis(poolEntry.lastAccessed, now) > aliveBypassWindowMs && !isConnectionAlive(poolEntry.connection))) {
closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE);
timeout=hardTimeout - elapsedMillis(startTime);
}
//成功獲得連接對象
else {
metricsTracker.recordBorrowStats(poolEntry, startTime);
return poolEntry.createProxyConnection(leakTaskFactory.schedule(poolEntry), now);
}
} while (timeout > 0L);
//超時了，拋出異常
metricsTracker.recordBorrowTimeoutStats(startTime);
throw createTimeoutException(startTime);
}
catch (InterruptedException e) {
Thread.currentThread().interrupt();
throw new SQLException(poolName + " - Interrupted during connection acquisition", e);
}
finally {
suspendResumeLock.release();
}
}
}getConnection() 方法展示了獲取連接的整個流程，其中 connectionBag 是用于存放連接對象的容器對象。如果從 connectionBag 獲得的連接不再滿足存活條件，那么會將其手動關閉，代碼如下：
void closeConnection(final PoolEntry poolEntry, final String closureReason)
{
//移除連接對象
if (connectionBag.remove(poolEntry)) {
final Connection connection=poolEntry.close();
//異步關閉連接
closeConnectionExecutor.execute(() -> {
quietlyCloseConnection(connection, closureReason);
//由于可用連接變少，將觸發填充連接池的任務
if (poolState==POOL_NORMAL) {
fillPool();
}
});
}
}注意到，只有當連接滿足下面條件中的其中一個時，會被執行 close。
如果連接存活時間超出最大生存時間(maxLifeTime)，或者距離上一次使用超過了idleTimeout，會被定時任務標記為清除狀態，清除狀態的連接在獲取的時候才真正 close。
由于我們把 idleTimeout 和 maxLifeTime 都設置得非常大，因此需重點檢查 isConnectionAlive 方法中的判斷，如下：
public class PoolBase{
//判斷連接是否存活
boolean isConnectionAlive(final Connection connection)
{
try {
try {
//設置 JDBC 連接的執行超時
setNetworkTimeout(connection, validationTimeout);
final int validationSeconds=(int) Math.max(1000L, validationTimeout) / 1000;
//如果沒有設置 TestQuery，使用 JDBC4 的校驗接口
if (isUseJdbc4Validation) {
return connection.isValid(validationSeconds);
}
//使用 TestQuery（如 select 1）語句對連接進行探測
try (Statement statement=connection.createStatement()) {
if (isNetworkTimeoutSupported !=TRUE) {
setQueryTimeout(statement, validationSeconds);
}
statement.execute(config.getConnectionTestQuery());
}
}
finally {
setNetworkTimeout(connection, networkTimeout);
if (isIsolateInternalQueries && !isAutoCommit) {
connection.rollback();
}
}
return true;
}
catch (Exception e) {
//發生異常時，將失敗信息記錄到上下文
lastConnectionFailure.set(e);
logger.warn("{} - Failed to validate connection {} ({}). Possibly consider using a shorter maxLifetime value.",
poolName, connection, e.getMessage());
return false;
}
}
}我們看到，在PoolBase.isConnectionAlive 方法中對連接執行了一系列的探測，如果發生異常還會將異常信息記錄到當前的線程上下文中。隨后，在 HikariPool 拋出異常時會將最后一次檢測失敗的異常也一同收集，如下：
private SQLException createTimeoutException(long startTime)
{
logPoolState("Timeout failure ");
metricsTracker.recordConnectionTimeout();
String sqlState=null;
//獲取最后一次連接失敗的異常
final Throwable originalException=getLastConnectionFailure();
if (originalException instanceof SQLException) {
sqlState=((SQLException) originalException).getSQLState();
}
//拋出異常
final SQLException connectionException=new SQLTransientConnectionException(poolName + " - Connection is not available, request timed out after " + elapsedMillis(startTime) + "ms.", sqlState, originalException);
if (originalException instanceof SQLException) {
connectionException.setNextException((SQLException) originalException);
}
return connectionException;
}這里的異常消息和我們在業務服務中看到的異常日志基本上是吻合的，即除了超時產生的 “Connection is not available, request timed out after xxxms” 消息之外，日志中還伴隨輸出了校驗失敗的信息：
Caused by: java.sql.SQLException: Connection.setNetworkTimeout cannot be called on a closed connection
at org.mariadb.jdbc.internal.util.exceptions.ExceptionMapper.getSqlException(ExceptionMapper.java:211) ~[mariadb-java-client-2.2.6.jar!/:?]
at org.mariadb.jdbc.MariaDbConnection.setNetworkTimeout(MariaDbConnection.java:1632) ~[mariadb-java-client-2.2.6.jar!/:?]
at com.zaxxer.hikari.pool.PoolBase.setNetworkTimeout(PoolBase.java:541) ~[HikariCP-2.7.9.jar!/:?]
at com.zaxxer.hikari.pool.PoolBase.isConnectionAlive(PoolBase.java:162) ~[HikariCP-2.7.9.jar!/:?]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:172) ~[HikariCP-2.7.9.jar!/:?]
at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:148) ~[HikariCP-2.7.9.jar!/:?]
at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-2.7.9.jar!/:?]到這里，我們已經將應用獲得連接的代碼大致梳理了一遍，整個過程如下圖所示：
從執行邏輯上看，連接池的處理并沒有問題，相反其在許多細節上都考慮到位了。在對非存活連接執行 close 時，同樣調用了 removeFromBag 動作將其從連接池中移除，因此也不應該存在僵尸連接對象的問題。
那么，我們之前的推測應該就是錯誤的！
在代碼分析之余，開發同學也注意到當前使用的 hikariCP 版本為 3.4.5，而環境上出問題的業務服務卻是 2.7.9 版本，這仿佛預示著什么… 讓我們再次假設 hikariCP 2.7.9 版本存在某種未知的 BUG，導致了問題的產生。
為了進一步分析連接池對于服務端故障的行為處理，我們嘗試在本地機器上進行模擬，這一次使用了 hikariCP 2.7.9 版本進行測試，并同時將 hikariCP 的日志級別設置為 DEBUG。
模擬場景中，會由 由本地應用程序連接本機的 MySQL 數據庫進行操作，步驟如下：
1. 初始化數據源，此時連接池 min-idle 設置為 10；
2. 每隔50ms 執行一次SQL操作，查詢當前的元數據表；
3. 將 MySQL 服務停止一段時間，觀察業務表現；
4. 將 MySQL 服務重新啟動，觀察業務表現。最終產生的日志如下：
//初始化過程，建立10個連接
DEBUG -HikariPool.logPoolState - Pool stats (total=1, active=1, idle=0, waiting=0)
DEBUG -HikariPool$PoolEntryCreator.call- Added connection MariaDbConnection@71ab7c09
DEBUG -HikariPool$PoolEntryCreator.call- Added connection MariaDbConnection@7f6c9c4c
DEBUG -HikariPool$PoolEntryCreator.call- Added connection MariaDbConnection@7b531779
...
DEBUG -HikariPool.logPoolState- After adding stats (total=10, active=1, idle=9, waiting=0)
//執行業務操作，成功
execute statement: true
test time -------1
execute statement: true
test time -------2
...
//停止MySQL
...
//檢測到無效連接
WARN -PoolBase.isConnectionAlive - Failed to validate connection MariaDbConnection@9225652 ((conn=38652)
Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
WARN -PoolBase.isConnectionAlive - Failed to validate connection MariaDbConnection@71ab7c09 ((conn=38653)
Connection.setNetworkTimeout cannot be called on a closed connection). Possibly consider using a shorter maxLifetime value.
//釋放連接
DEBUG -PoolBase.quietlyCloseConnection(PoolBase.java:134) - Closing connection MariaDbConnection@9225652: (connection is dead)
DEBUG -PoolBase.quietlyCloseConnection(PoolBase.java:134) - Closing connection MariaDbConnection@71ab7c09: (connection is dead)
//嘗試創建連接失敗
DEBUG -HikariPool.createPoolEntry - Cannot acquire connection from data source
java.sql.SQLNonTransientConnectionException: Could not connect to address=(host=localhost)(port=3306)(type=master) :
Socket fail to connect to host:localhost, port:3306. Connection refused: connect
Caused by: java.sql.SQLNonTransientConnectionException: Socket fail to connect to host:localhost, port:3306. Connection refused: connect
at internal.util.exceptions.ExceptionFactory.createException(ExceptionFactory.java:73) ~[mariadb-java-client-2.6.0.jar:?]
...
//持續失敗.. 直到MySQL重啟
//重啟后，自動創建連接成功
DEBUG -HikariPool$PoolEntryCreator.call -Added connection MariaDbConnection@42c5503e
DEBUG -HikariPool$PoolEntryCreator.call -Added connection MariaDbConnection@695a7435
//連接池狀態，重新建立10個連接
DEBUG -HikariPool.logPoolState(HikariPool.java:421) -After adding stats (total=10, active=1, idle=9, waiting=0)
//執行業務操作，成功（已經自愈）
execute statement: true從日志上看，hikariCP 還是能成功檢測到壞死的連接并將其踢出連接池，一旦 MySQL 重新啟動，業務操作又能自動恢復成功了。根據這個結果，基于 hikariCP 版本問題的設想也再次落空，研發同學再次陷入焦灼。
多方面求證無果之后，我們最終嘗試在業務服務所在的容器內進行抓包，看是否能發現一些蛛絲馬跡。
進入故障容器，執行 tcpdump -i eth0 tcp port 30052 進行抓包，然后對業務接口發起訪問。
此時令人詭異的事情發生了，沒有任何網絡包產生！而業務日志在 30s 之后也出現了獲取連接失敗的異常。
我們通過 netstat 命令檢查網絡連接，發現只有一個 ESTABLISHED 狀態的 TCP 連接。
也就是說，當前業務實例和 MySQL 服務端是存在一個建好的連接的，但為什么業務還是報出可用連接呢？
推測可能原因有二：
對于原因一，很快就可以被推翻，一來當前服務并沒有什么定時器任務，二來就算該連接被占用，按照連接池的原理，只要沒有達到上限，新的業務請求應該會促使連接池進行新連接的建立，那么無論是從 netstat 命令檢查還是 tcpdump 的結果來看，不應該一直是只有一個連接的狀況。
那么，情況二的可能性就很大了。帶著這個思路，繼續分析 Java 進程的線程棧。
執行 kill -3 pid 將線程棧輸出后分析，果不其然，在當前 thread stack 中發現了如下的條目：
"HikariPool-1 connection adder" #121 daemon prio=5 os_prio=0 tid=0x00007f1300021800 nid=0xad runnable [0x00007f12d82e5000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.FilterInputStream.read(FilterInputStream.java:133)
at org.mariadb.jdbc.internal.io.input.ReadAheadBufferedStream.fillBuffer(ReadAheadBufferedStream.java:129)
at org.mariadb.jdbc.internal.io.input.ReadAheadBufferedStream.read(ReadAheadBufferedStream.java:102)
- locked <0x00000000d7f5b480> (a org.mariadb.jdbc.internal.io.input.ReadAheadBufferedStream)
at org.mariadb.jdbc.internal.io.input.StandardPacketInputStream.getPacketArray(StandardPacketInputStream.java:241)
at org.mariadb.jdbc.internal.io.input.StandardPacketInputStream.getPacket(StandardPacketInputStream.java:212)
at org.mariadb.jdbc.internal.com.read.ReadInitialHandShakePacket.<init>(ReadInitialHandShakePacket.java:90)
at org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol.createConnection(AbstractConnectProtocol.java:480)
at org.mariadb.jdbc.internal.protocol.AbstractConnectProtocol.connectWithoutProxy(AbstractConnectProtocol.java:1236)
at org.mariadb.jdbc.internal.util.Utils.retrieveProxy(Utils.java:610)
at org.mariadb.jdbc.MariaDbConnection.newConnection(MariaDbConnection.java:142)
at org.mariadb.jdbc.Driver.connect(Driver.java:86)
at com.zaxxer.hikari.util.DriverDataSource.getConnection(DriverDataSource.java:138)
at com.zaxxer.hikari.pool.PoolBase.newConnection(PoolBase.java:358)
at com.zaxxer.hikari.pool.PoolBase.newPoolEntry(PoolBase.java:206)
at com.zaxxer.hikari.pool.HikariPool.createPoolEntry(HikariPool.java:477)這里顯示 HikariPool-1 connection adder 這個線程一直處于 socketRead 的可執行狀態。從命名上看該線程應該是 HikariCP 連接池用于建立連接的任務線程，socket 讀操作則來自于 MariaDbConnection.newConnection() 這個方法，即 mariadb-java-client 驅動層建立 MySQL 連接的一個操作，其中 ReadInitialHandShakePacket 初始化則屬于 MySQL 建鏈協議中的一個環節。
簡而言之，上面的線程剛好處于建鏈的一個過程態，關于 mariadb 驅動和 MySQL 建鏈的過程大致如下：
MySQL 建鏈首先是建立 TCP 連接（三次握手），客戶端會讀取 MySQL 協議的一個初始化握手消息包，內部包含 MySQL 版本號，鑒權算法等等信息，之后再進入身份鑒權的環節。
這里的問題就在于 ReadInitialHandShakePacket 初始化（讀取握手消息包）一直處于 socket read 的一個狀態。
如果此時 MySQL 遠端主機故障了，那么該操作就會一直卡住。而此時的連接雖然已經建立（處于 ESTABLISHED 狀態），但卻一直沒能完成協議握手和后面的身份鑒權流程，即該連接只能算一個半成品（無法進入 hikariCP 連接池的列表中）。從故障服務的 DEBUG 日志也可以看到，連接池持續是沒有可用連接的，如下：
DEBUG HikariPool.logPoolState --> Before cleanup stats (total=0, active=0, idle=0, waiting=3)另一個需要解釋的問題則是，這樣一個 socket read 操作的阻塞是否就造成了整個連接池的阻塞呢？
經過代碼走讀，我們再次梳理了 hikariCP 建立連接的一個流程，其中涉及到幾個模塊：
HouseKeeper 在連接池初始化后的 100ms 觸發執行，其調用 fillPool() 方法完成連接池的填充，例如 min-idle 是10，那么初始化就會創建10個連接。ConnectionBag 維護了當前連接對象的列表，該模塊還維護了請求連接者(waiters)的一個計數器，用于評估當前連接數的需求。
其中，borrow 方法的邏輯如下：
public T borrow(long timeout, final TimeUnit timeUnit) throws InterruptedException
{
// 嘗試從 thread-local 中獲取
final List<Object> list=threadList.get();
for (int i=list.size() - 1; i >=0; i--) {
...
}
// 計算當前等待請求的任務
final int waiting=waiters.incrementAndGet();
try {
for (T bagEntry : sharedList) {
if (bagEntry.compareAndSet(STATE_NOT_IN_USE, STATE_IN_USE)) {
//如果獲得了可用連接，會觸發填充任務
if (waiting > 1) {
listener.addBagItem(waiting - 1);
}
return bagEntry;
}
}
//沒有可用連接，先觸發填充任務
listener.addBagItem(waiting);
//在指定時間內等待可用連接進入
timeout=timeUnit.toNanos(timeout);
do {
final long start=currentTime();
final T bagEntry=handoffQueue.poll(timeout, NANOSECONDS);
if (bagEntry==null || bagEntry.compareAndSet(STATE_NOT_IN_USE, STATE_IN_USE)) {
return bagEntry;
}
timeout -=elapsedNanos(start);
} while (timeout > 10_000);
return null;
}
finally {
waiters.decrementAndGet();
}
}注意到，無論是有沒有可用連接，該方法都會觸發一個 listener.addBagItem() 方法，HikariPool 對該接口的實現如下：
public void addBagItem(final int waiting)
{
final boolean shouldAdd=waiting - addConnectionQueueReadOnlyView.size() >=0; // Yes, >=is intentional.
if (shouldAdd) {
//調用 AddConnectionExecutor 提交創建連接的任務
addConnectionExecutor.submit(poolEntryCreator);
}
else {
logger.debug("{} - Add connection elided, waiting {}, queue {}", poolName, waiting, addConnectionQueueReadOnlyView.size());
}
}
PoolEntryCreator 則實現了創建連接的具體邏輯，如下：
public class PoolEntryCreator{
@Override
public Boolean call()
{
long sleepBackoff=250L;
//判斷是否需要建立連接
while (poolState==POOL_NORMAL && shouldCreateAnotherConnection()) {
//創建 MySQL 連接
final PoolEntry poolEntry=createPoolEntry();
if (poolEntry !=null) {
//建立連接成功，直接返回。
connectionBag.add(poolEntry);
logger.debug("{} - Added connection {}", poolName, poolEntry.connection);
if (loggingPrefix !=null) {
logPoolState(loggingPrefix);
}
return Boolean.TRUE;
}
...
}
// Pool is suspended or shutdown or at max size
return Boolean.FALSE;
}
} 由此可見，AddConnectionExecutor 采用了單線程的設計，當產生新連接需求時，會異步觸發 PoolEntryCreator 任務進行補充。其中 PoolEntryCreator. createPoolEntry() 會完成 MySQL 驅動連接建立的所有事情，而我們的情況則恰恰是 MySQL 建鏈過程產生了永久性阻塞。因此無論后面怎么獲取連接，新來的建鏈任務都會一直排隊等待，這便導致了業務上一直沒有連接可用。
下面這個圖說明了 hikariCP 的建鏈過程：
好了，讓我們在回顧一下前面關于可靠性測試的場景：
首先，MySQL 主實例發生故障，而緊接著 hikariCP 則檢測到了壞的連接(connection is dead)并將其釋放，在釋放關閉連接的同時又發現連接數需要補充，進而立即觸發了新的建鏈請求。
而問題就剛好出在這一次建鏈請求上，TCP 握手的部分是成功了（客戶端和 MySQL VM 上 nodePort 完成連接），但在接下來由于當前的 MySQL 容器已經停止（此時 VIP 也切換到了另一臺 MySQL 實例上），因此客戶端再也無法獲得原 MySQL 實例的握手包響應（該握手屬于MySQL應用層的協議），此時便陷入了長時間的阻塞式 socketRead 操作。而建鏈請求任務恰恰好采用了單線程運作，進一步則導致了所有業務的阻塞。
在了解了事情的來龍去脈之后，我們主要考慮從兩方面進行優化：
對于優化點一，我們一致認為用處并不大，如果連接出現了掛死那么相當于線程資源已經泄露，對服務后續的穩定運行十分不利，而且 hikariCP 在這里也已經將其寫死了。因此關鍵的方案還是避免阻塞式的調用。
查閱了 mariadb-java-client 官方文檔后，發現可以在 JDBC URL 中指定網絡IO 的超時參數，如下：
具體參考：https://mariadb.com/kb/en/about-mariadb-connector-j/
如描述所說的，socketTimeout 可以設置 socket 的 SO_TIMEOUT 屬性，從而達到控制超時時間的目的。默認是 0，即不超時。
我們在 MySQL JDBC URL 中加入了相關的參數，如下：
spring.datasource.url=jdbc:mysql://10.0.71.13:33052/appdb?socketTimeout=60000&connectTimeout=30000&serverTimezone=UTC此后對 MySQL 可靠性場景進行多次驗證，發現連接掛死的現象已經不再出現，此時問題得到解決。
本次分享了一次關于 MySQL 連接掛死問題排查的心路歷程，由于環境搭建的工作量巨大，而且該問題復現存在偶然性，整個分析過程還是有些坎坷的（其中也踩了坑）。的確，我們很容易被一些表面的現象所迷惑，而覺得問題很難解決時，更容易帶著偏向性思維去處理問題。例如本例中曾一致認為連接池出現了問題，但實際上卻是由于 MySQL JDBC 驅動（mariadb driver）的一個不嚴謹的配置所導致。
從原則上講，應該避免一切可能導致資源掛死的行為。如果我們能在前期對代碼及相關配置做好充分的排查工作，相信 996 就會離我們越來越遠。
如果感覺小編寫得不錯，請素質三連：點贊+轉發+關注。我會努力寫出更好的作品分享給大家。更多JAVA進階學習資料小編已打包好，可以關注私信找我領取哦
原文 https://my.oschina.net/u/4526289/blog/4727491