詭異的druid連結池連結斷開故障經驗總結

摘要： 背景 症狀 排查 修復 背景 最近在陸續做機房升級相關工作，配合DBA對產線資料庫連結方式做個調整，將原來直接連結讀庫的地址切換到統一的讀負載均衡的代理haproxy 上，方便機櫃和伺服器的搬遷。 切換之後線...

• 背景
• 症狀
• 排查
• 修復

背景

最近在陸續做機房升級相關工作，配合DBA對產線資料庫連結方式做個調整，將原來直接連結讀庫的地址切換到統一的讀負載均衡的代理haproxy 上，方便機櫃和伺服器的搬遷。

切換之後線上時不時的會發生discard connection 錯誤，導致程式報500 錯誤，但不是每次都必現的。

開發框架: spring boot+mybatis+druid+shardingJDBC

網路架構:

appserver->mysql(master) 寫

appserver->haproxy->mysql(slave)/n 讀

第一反應肯定是因為這次的讀庫地址的變動引起的問題，覺得問題應該是druid 連結池中的connection 保活策略沒起作用，只要做下配置修改應該就可以了。結果這個問題讓我們排查了好幾天，我們竟然踩到了千年難遇的深坑。

這個問題排查的很坎坷，一次次的吐血，最終我們定位到問題並且優雅的修復了，我們一起來體驗下這個一次一次讓你絕望一次一次打臉的過程。

症狀

先說故障症狀，經常出現如下錯誤：

discard connectioncom.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 72,557 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.

根據錯誤日誌初步判斷肯定是與db 之間的連結已經斷開，嘗試使用了一個已經斷開的連結才會引起這個錯誤發生。但是根據我們對druid 瞭解，druid 有連結檢查功能，按理不會拿到一個無效連結才對，帶著這個線索我們上路了。

排查

為了準確的知道db 的連結的存活時間，瞭解到haproxy 對轉發的db tcp 連結空閒時間在1m 之內，超過1m 不活動就會被關掉。也就說我們與db 之間的原來的長連結在1m 之內會被斷開。我們先不管這個時間設定的是否符合所有的大併發場景，至少在druid 的連結池裡會有有效連結檢查，應該不會拿到無效連結才對，我們做了配置調整。

我們看下druid 跟連結時間相關的配置：

datasource.druid.validationQuery=SELECT 1
datasource.druid.validationQueryTimeout=2000
datasource.druid.testWhileIdle=true
datasource.druid.minEvictableIdleTimeMillis=100000
datasource.druid.timeBetweenEvictionRunsMillis=20000

配置的每項的意思這裡就不解釋了。

我們啟用了testWhileIdle 配置，讓每次拿取連結的時候發起檢查。根據timeBetweenEvictionRunsMillis 的配置只有大於這個時間druid 才會發起檢查，所以可能的場景是拿到一個即將過期的連結，根據這個線索我們調整這個時間為20000ms ，也就是超過20s 會檢查當前拿取的連結確定是否有效，檢查的方式應該是使用validationQuery 配置的sql 語句才對，但是發現我們並找不到任何有關於SELECT 1 的痕跡。

為什麼你死活找不到 SELECT 1

首先要搞清楚validationQuery 為什麼沒起作用，帶著這個疑問開始debug druid 原始碼。

if (isTestWhileIdle()) {
final long currentTimeMillis = System.currentTimeMillis();
final long lastActiveTimeMillis = poolableConnection.getConnectionHolder().getLastActiveTimeMillis();
final long idleMillis = currentTimeMillis - lastActiveTimeMillis;
long timeBetweenEvictionRunsMillis = this.getTimeBetweenEvictionRunsMillis();
if (timeBetweenEvictionRunsMillis <= 0) {
timeBetweenEvictionRunsMillis = DEFAULT_TIME_BETWEEN_EVICTION_RUNS_MILLIS;
}

if (idleMillis >= timeBetweenEvictionRunsMillis) {
boolean validate = testConnectionInternal(poolableConnection.getConnection());
if (!validate) {
if (LOG.isDebugEnabled()) {
LOG.debug("skip not validate connection.");
}

discardConnection(realConnection);
continue;
}
}
}
}

閒置時間肯定會有大於timeBetweenEvictionRunsMillis 時間的，會發起testConnectionInternal 方法檢查。我們繼續跟進去看，

protected boolean testConnectionInternal(DruidConnectionHolder holder, Connection conn) {
boolean valid = validConnectionChecker.isValidConnection(conn, validationQuery, validationQueryTimeout);

內部會使用validConnectionChecker 檢查物件發起檢查。

public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) throws Exception {
if (conn.isClosed()) {
return false;
}

if (usePingMethod) {
if (conn instanceof DruidPooledConnection) {
conn = ((DruidPooledConnection) conn).getConnection();
}

if (conn instanceof ConnectionProxy) {
conn = ((ConnectionProxy) conn).getRawObject();
}

if (clazz.isAssignableFrom(conn.getClass())) {
if (validationQueryTimeout < 0) {
validationQueryTimeout = DEFAULT_VALIDATION_QUERY_TIMEOUT;
}

try {
ping.invoke(conn, true, validationQueryTimeout * 1000);
} catch (InvocationTargetException e) {
Throwable cause = e.getCause();
if (cause instanceof SQLException) {
throw (SQLException) cause;
}
throw e;
}
return true;
}
}

String query = validateQuery;
if (validateQuery == null || validateQuery.isEmpty()) {
query = DEFAULT_VALIDATION_QUERY;
}

Statement stmt = null;
ResultSet rs = null;
try {
stmt = conn.createStatement();
if (validationQueryTimeout > 0) {
stmt.setQueryTimeout(validationQueryTimeout);
}
rs = stmt.executeQuery(query);
return true;
} finally {
JdbcUtils.close(rs);
JdbcUtils.close(stmt);
}

}

debug 這裡才發現，druid 預設採用的是mysql.ping 來做連結有效性檢查。

druid 預設採用msyql.ping 協議檢查

那是不是用msyql.ping 協議並不會讓mysql 重新滑動session 閒置時間，帶著這個問題開啟information_schema.processlist 程序列表檢視會不會重新整理會話時間，通過 debug發現是會重新整理時間的，說明沒有問題，這條線索算是斷了。

haproxy tiemout主動close上下游連結

調整方向，開始懷疑是不是haproxy 的一些策略導致連結失效，開始初步懷疑haproxy 的輪訓轉發後端連結是不是有相關會話保持方式，是不是我們配置有誤導致haproxy 的連結和mysql 連結篡位了。

當然這個猜想有點誇張，但是沒辦法，技術人員就要有懷疑一切的態度。

為了還原產線的網路路線，我在本地搭了一個haproxy ，瞭解下他的工作原理和配置，圖方便我就用了yum順手裝了一個，版本是HA-Proxy version 1.5.18 不知道是我本地環境問題還是這個版本的bug ，我們配置的mode tcp 活動檢查一直不生效。

listen service 127.0.0.1:60020
mode tcp
balance roundrobin
option tcplog
server server1 192.168.36.66:3306 check inter 2000 rise 2 fall 3
server server2 192.168.36.66:3306 check inter 2000 rise 2 fall 3

由於haproxy 活動檢查一直不通過，所以無法轉發我的連結，搞了半天我只能手動裝了一個低版本的haproxy HA-Proxy version 1.4.14 。

完整的配置：

defaults
mode tcp
retries 3
option redispatch
option abortonclose
maxconn 32000
timeout connect 2s 
timeout client 5m 
timeout server 5m 


listen test1
bind 0.0.0.0:60000
mode tcp
balance roundrobin
server s1 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s
server s2 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s
server s3 192.168.36.66:3306 weight 1 maxconn 10000 check inter 10s

1.4的版本順利完成活動檢查。

我使用haproxy 進行debug，除錯下來也都沒有問題，也翻了下haproxy 如何轉發連結的，內部通過會話的方式保持兩個連結的關係，如果是tcp 長連結應該不會出現什麼問題。haproxy 在http 模式下有會話保持方式，tcp 應該是直接捆綁的方式，一旦到timeout 時間會主動close 和mysql 的連結，而且沒有出現篡位的問題。到這裡線索又斷了。

自定義 ValidConnectionChecker 埋點日誌

沒有辦法，只能試著埋點druid 的檢查日誌，排查內部上一次的 check和報錯之間的時間差和connectionId 是不是一致的。

public class MySqlValidConnectionCheckerDebug extends MySqlValidConnectionChecker {

@Override
public boolean isValidConnection(Connection conn, String validateQuery, int validationQueryTimeout) {

Long connId = 0L;
try {
Field connField = ConnectionImpl.class.getDeclaredField("connectionId");
connField.setAccessible(true);
connId = (Long) connField.get(((ConnectionProxyImpl) conn).getConnectionRaw());
} catch (Exception e) {
log.error("valid connection error", e);
} finally {
log.info("valid connection ok. conn:" + connId);
}

return true;
}

為了拿到connectionId 只能反射獲取，在本地debug下沒問題，能正常拿到connectionId ，但是發到驗證環境進行驗證的時候報錯了，覺得奇怪，仔細看了下原來開發環境的配置和驗證和生產的不一樣，開發環境沒有走讀寫分離。

驗證和生產都是使用了mysql 的replication 的機制，所以導致我反射獲取的程式碼報錯。

datasource.druid.url=jdbc:mysql:replication

通過debug發現，原來 __druid__的connection 是JDBC4Connection ，變成了ReplicationConnection ，而且裡面包裝了兩個connection ，一個masterconnection ，一個slaveconnection ，似乎問題有點浮現了。

通過debug發現druid 的檢查還是會正常走到，當走到ReplicationConnection 內部的時候ReplicationConnection 有一個currentConnection ，這個連結是會在masterConnection 和slaveConnection 之間切換，切換的依據是readOnly 引數。

在檢查的時候由於druid 並不感知上層的引數，readOnly 也就不會設定。所以走的是masterConnection ，但是在程式裡用的時候通過spring 的TransactionManager 將readOnly 傳播到了ShardingJDBC ，ShardingJDBC 在設定到ReplicationConnection 上，最後導致真正在使用的時候其實使用的是slaveConnection 。

找到這個問題之後去druid github Issues 搜尋了下果然有人提過這個問題，在高版本的druid 中已經修復這個問題了。

修復

修復這個問題有兩個方法，第一個方法，建議升級 druid，裡面已經有MySqlReplicationValidConnectionChecker 檢查器專門用來解決這個問題。第二個方法就是自己實現ValidConnectionChecker 檢查器，但是會有在將來出現bug的可能性。

由於時間關係文章只講了主要的排查路線，事實上我們陸續花了一週多時間，再加上週末連續趴上十幾個小時才找到這根本問題。

這個問題之所以難定位的原因主要是牽扯的東西太多，框架層面、網路連結層面、mysql伺服器層面，haproxy代理等等，當然其中也繞了很多彎路。。

下面分享在這個整個排查過程中的一些技術收穫。

相關技術問題

1.mysqlConenction提供了ping方法用來做活動檢查，預設MySqlValidConnectionChecker使用的是pinginternal。

ping = clazz.getMethod("pingInternal", boolean.class, int.class);

2.低版本的druid不支援自定義 ValidConnectionChecker 來做個性化的檢查。

3.druid 的test方法使用注意事項，testOnBorrow 在獲取連結的時候進行檢查，與testWhileIdle是護持關係。

if (isTestOnBorrow()) {
} else {
if (isTestWhileIdle()) {

3.kill mysql processlist 程序會話到連結端tcp狀態有延遲，這是tcp的四次斷開延遲。

4.haproxy 1.5.18 版本 mode tcp check不執行，健康檢查設定無效。

5.mysql replication connection master/slave切換邏輯需要注意，會不會跟上下油的連結池組合使用出現bug，尤其是分庫不表、讀寫分離、自定義分片。

6.排查mysql伺服器的問題時，開啟各種日誌，操作日誌，binlog日誌。

7.springtransactionmanagenent 事務傳播特性會影響下游資料來源的選擇，setreadonly、setautocommit。

8.低版本的 druid MySqlValidConnectionChecker 永遠執行不到 ReplicationConnection ping 方法。

作者：王清培(滬江網資深架構師)