最近在陸續(xù)做機(jī)房升級(jí)相關(guān)工作，配合DBA對(duì)產(chǎn)線數(shù)據(jù)庫(kù)鏈接方式做個(gè)調(diào)整，將原來(lái)直接鏈接讀庫(kù)的地址切換到統(tǒng)一的讀負(fù)載均衡的代理 haproxy 上，方便機(jī)柜和服務(wù)器的搬遷。
切換之后線上時(shí)不時(shí)的會(huì)發(fā)生 discard connection 錯(cuò)誤，導(dǎo)致程序報(bào) 500 錯(cuò)誤，但不是每次都必現(xiàn)的。
開(kāi)發(fā)框架: spring boot+mybatis+druid+shardingJDBC
網(wǎng)絡(luò)架構(gòu):
appserver->mysql(master) 寫
appserver->haproxy->mysql(slave)/n 讀
第一反應(yīng)肯定是因?yàn)檫@次的讀庫(kù)地址的變動(dòng)引起的問(wèn)題，覺(jué)得問(wèn)題應(yīng)該是 druid 鏈接池中的 connection ?；畈呗詻](méi)起作用，只要做下配置修改應(yīng)該就可以了。結(jié)果這個(gè)問(wèn)題讓我們排查了好幾天，我們竟然踩到了千年難遇的深坑。
這個(gè)問(wèn)題排查的很坎坷，一次次的吐血，最終我們定位到問(wèn)題并且優(yōu)雅的修復(fù)了，我們一起來(lái)體驗(yàn)下這個(gè)一次一次讓你絕望一次一次打臉的過(guò)程。
先說(shuō)故障癥狀，經(jīng)常出現(xiàn)如下錯(cuò)誤：
discard connection
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failureThe last packet successfully received from the server was 72,557 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago.
根據(jù)錯(cuò)誤日志初步判斷肯定是與 db 之間的鏈接已經(jīng)斷開(kāi)，嘗試使用了一個(gè)已經(jīng)斷開(kāi)的鏈接才會(huì)引起這個(gè)錯(cuò)誤發(fā)生。但是根據(jù)我們對(duì) druid 了解，druid 有鏈接檢查功能，按理不會(huì)拿到一個(gè)無(wú)效鏈接才對(duì)，帶著這個(gè)線索我們上路了。
為了準(zhǔn)確的知道 db 的鏈接的存活時(shí)間，了解到 haproxy 對(duì)轉(zhuǎn)發(fā)的 db tcp 鏈接空閑時(shí)間在 1m 之內(nèi)，超過(guò) 1m 不活動(dòng)就會(huì)被關(guān)掉。也就說(shuō)我們與 db 之間的原來(lái)的長(zhǎng)鏈接在 1m 之內(nèi)會(huì)被斷開(kāi)。我們先不管這個(gè)時(shí)間設(shè)置的是否符合所有的大并發(fā)場(chǎng)景，至少在 druid 的鏈接池里會(huì)有有效鏈接檢查，應(yīng)該不會(huì)拿到無(wú)效鏈接才對(duì)，我們做了配置調(diào)整。
我們看下 druid 跟鏈接時(shí)間相關(guān)的配置：
重慶分公司
重慶分公司
datasource.druid.validationQuery=SELECT 1
datasource.druid.validationQueryTimeout=2000
datasource.druid.testWhileIdle=true
datasource.druid.minEvictableIdleTimeMillis=100000
datasource.druid.timeBetweenEvictionRunsMillis=20000配置的每項(xiàng)的意思這里就不解釋了。
我們啟用了 testWhileIdle 配置，讓每次拿取鏈接的時(shí)候發(fā)起檢查。根據(jù) timeBetweenEvictionRunsMillis 的配置只有大于這個(gè)時(shí)間 druid 才會(huì)發(fā)起檢查，所以可能的場(chǎng)景是拿到一個(gè)即將過(guò)期的鏈接，根據(jù)這個(gè)線索我們調(diào)整這個(gè)時(shí)間為 20000ms，也就是超過(guò) 20s 會(huì)檢查當(dāng)前拿取的鏈接確定是否有效，檢查的方式應(yīng)該是使用 validationQuery 配置的 sql 語(yǔ)句才對(duì)，但是發(fā)現(xiàn)我們并找不到任何有關(guān)于 SELECT 1 的痕跡。
首先要搞清楚 validationQuery 為什么沒(méi)起作用，帶著這個(gè)疑問(wèn)開(kāi)始 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;
}
}
}
}閑置時(shí)間肯定會(huì)有大于 timeBetweenEvictionRunsMillis 時(shí)間的，會(huì)發(fā)起 testConnectionInternal 方法檢查。我們繼續(xù)跟進(jìn)去看，
protected boolean testConnectionInternal(DruidConnectionHolder holder, Connection conn) {
boolean valid = validConnectionChecker.isValidConnection(conn, validationQuery, validationQueryTimeout);
內(nèi)部會(huì)使用 validConnectionChecker 檢查對(duì)象發(fā)起檢查。
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 這里才發(fā)現(xiàn)，druid 默認(rèn)采用的是 mysql.ping 來(lái)做鏈接有效性檢查。
那是不是用 msyql.ping 協(xié)議并不會(huì)讓 mysql 重新滑動(dòng) session 閑置時(shí)間，帶著這個(gè)問(wèn)題打開(kāi) __information_schema.processlist__ 進(jìn)程列表查看會(huì)不會(huì)刷新會(huì)話時(shí)間，通過(guò) debug發(fā)現(xiàn)是會(huì)刷新時(shí)間的，說(shuō)明沒(méi)有問(wèn)題，這條線索算是斷了。
調(diào)整方向，開(kāi)始懷疑是不是 haproxy 的一些策略導(dǎo)致鏈接失效，開(kāi)始初步懷疑 haproxy 的輪訓(xùn)轉(zhuǎn)發(fā)后端鏈接是不是有相關(guān)會(huì)話保持方式，是不是我們配置有誤導(dǎo)致 haproxy 的鏈接和 mysql 鏈接篡位了。
當(dāng)然這個(gè)猜想有點(diǎn)夸張，但是沒(méi)辦法，技術(shù)人員就要有懷疑一切的態(tài)度。
為了還原產(chǎn)線的網(wǎng)絡(luò)路線，我在本地搭了一個(gè) haproxy，了解下他的工作原理和配置，圖方便我就用了yum順手裝了一個(gè)，版本是 HA-Proxy version 1.5.18 不知道是我本地環(huán)境問(wèn)題還是這個(gè)版本的 bug，我們配置的 mode tcp 活動(dòng)檢查一直不生效。
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 活動(dòng)檢查一直不通過(guò)，所以無(wú)法轉(zhuǎn)發(fā)我的鏈接，搞了半天我只能手動(dòng)裝了一個(gè)低版本的 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 10s1.4 的版本順利完成活動(dòng)檢查。
我使用 haproxy 進(jìn)行debug，調(diào)試下來(lái)也都沒(méi)有問(wèn)題，也翻了下 haproxy 如何轉(zhuǎn)發(fā)鏈接的，內(nèi)部通過(guò)會(huì)話的方式保持兩個(gè)鏈接的關(guān)系，如果是 tcp 長(zhǎng)鏈接應(yīng)該不會(huì)出現(xiàn)什么問(wèn)題。haproxy 在 http 模式下有會(huì)話保持方式，tcp 應(yīng)該是直接捆綁的方式，一旦到 timeout 時(shí)間會(huì)主動(dòng) close 和 mysql 的鏈接，而且沒(méi)有出現(xiàn)篡位的問(wèn)題。到這里線索又?jǐn)嗔恕?/p>
沒(méi)有辦法，只能試著埋點(diǎn) druid 的檢查日志，排查內(nèi)部上一次的 check和報(bào)錯(cuò)之間的時(shí)間差和 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下沒(méi)問(wèn)題，能正常拿到 connectionId，但是發(fā)到驗(yàn)證環(huán)境進(jìn)行驗(yàn)證的時(shí)候報(bào)錯(cuò)了，覺(jué)得奇怪，仔細(xì)看了下原來(lái)開(kāi)發(fā)環(huán)境的配置和驗(yàn)證和生產(chǎn)的不一樣，開(kāi)發(fā)環(huán)境沒(méi)有走讀寫分離。
驗(yàn)證和生產(chǎn)都是使用了 mysql 的 replication 的機(jī)制，所以導(dǎo)致我反射獲取的代碼報(bào)錯(cuò)。
datasource.druid.url=jdbc:mysql:replication通過(guò)debug發(fā)現(xiàn)，原來(lái) druid的 connection 是 JDBC4Connection ，變成了 ReplicationConnection ，而且里面包裝了兩個(gè) connection ，一個(gè) masterconnection ，一個(gè) slaveconnection ，似乎問(wèn)題有點(diǎn)浮現(xiàn)了。
通過(guò)debug發(fā)現(xiàn) druid 的檢查還是會(huì)正常走到，當(dāng)走到 ReplicationConnection 內(nèi)部的時(shí)候 ReplicationConnection 有一個(gè) currentConnection ，這個(gè)鏈接是會(huì)在 masterConnection 和 slaveConnection 之間切換，切換的依據(jù)是 readOnly 參數(shù)。
在檢查的時(shí)候由于 druid 并不感知上層的參數(shù)，readOnly 也就不會(huì)設(shè)置。所以走的是 masterConnection ，但是在程序里用的時(shí)候通過(guò) spring 的 TransactionManager 將 readOnly 傳播到了 ShardingJDBC ， ShardingJDBC 在設(shè)置到 ReplicationConnection 上，最后導(dǎo)致真正在使用的時(shí)候其實(shí)使用的是 slaveConnection。
找到這個(gè)問(wèn)題之后去 druid github Issues 搜索了下果然有人提過(guò)這個(gè)問(wèn)題，在高版本的 druid 中已經(jīng)修復(fù)這個(gè)問(wèn)題了。
修復(fù)這個(gè)問(wèn)題有兩個(gè)方法，第一個(gè)方法，建議升級(jí) druid，里面已經(jīng)有 MySqlReplicationValidConnectionChecker 檢查器專門用來(lái)解決這個(gè)問(wèn)題。第二個(gè)方法就是自己實(shí)現(xiàn) ValidConnectionChecker 檢查器，但是會(huì)有在將來(lái)出現(xiàn)bug的可能性。
由于時(shí)間關(guān)系文章只講了主要的排查路線，事實(shí)上我們陸續(xù)花了一周多時(shí)間，再加上周末連續(xù)趴上十幾個(gè)小時(shí)才找到這根本問(wèn)題。
這個(gè)問(wèn)題之所以難定位的原因主要是牽扯的東西太多，框架層面、網(wǎng)絡(luò)鏈接層面、mysql服務(wù)器層面，haproxy代理等等，當(dāng)然其中也繞了很多彎路。。
下面分享在這個(gè)整個(gè)排查過(guò)程中的一些技術(shù)收獲。
1.mysqlConenction提供了ping方法用來(lái)做活動(dòng)檢查，默認(rèn)MySqlValidConnectionChecker使用的是pinginternal。
ping = clazz.getMethod("pingInternal", boolean.class, int.class);2.低版本的druid不支持自定義 ValidConnectionChecker 來(lái)做個(gè)性化的檢查。
3.druid 的test方法使用注意事項(xiàng)，testOnBorrow 在獲取鏈接的時(shí)候進(jìn)行檢查，與testWhileIdle是互斥關(guān)系。
if (isTestOnBorrow()) {
} else {
if (isTestWhileIdle()) {3.kill mysql processlist 進(jìn)程會(huì)話到鏈接端tcp狀態(tài)有延遲，這是tcp的四次斷開(kāi)延遲。
4.haproxy 1.5.18 版本 mode tcp check不執(zhí)行，健康檢查設(shè)置無(wú)效。
5.mysql replication connection master/slave切換邏輯需要注意，會(huì)不會(huì)跟上下游的鏈接池組合使用出現(xiàn)bug，尤其是分庫(kù)不表、讀寫分離、自定義分片。
6.排查mysql服務(wù)器的問(wèn)題時(shí)，打開(kāi)各種日志，操作日志，binlog日志。
7.springtransactionmanagenent 事務(wù)傳播特性會(huì)影響下游數(shù)據(jù)源的選擇，setreadonly、setautocommit。
8.低版本的 druid MySqlValidConnectionChecker 永遠(yuǎn)執(zhí)行不到 ReplicationConnection ping 方法。
作者：王清培(滬江網(wǎng)資深架構(gòu)師)
另外有需要云服務(wù)器可以了解下創(chuàng)新互聯(lián)scvps.cn，海內(nèi)外云服務(wù)器15元起步，三天無(wú)理由+7*72小時(shí)售后在線，公司持有idc許可證，提供“云服務(wù)器、裸金屬服務(wù)器、高防服務(wù)器、香港服務(wù)器、美國(guó)服務(wù)器、虛擬主機(jī)、免備案服務(wù)器”等云主機(jī)租用服務(wù)以及企業(yè)上云的綜合解決方案，具有“安全穩(wěn)定、簡(jiǎn)單易用、服務(wù)可用性高、性價(jià)比高”等特點(diǎn)與優(yōu)勢(shì)，專為企業(yè)上云打造定制，能夠滿足用戶豐富、多元化的應(yīng)用場(chǎng)景需求。
