昨天夜里小伙伴上線新系統(tǒng)時巍虫，發(fā)現(xiàn)經(jīng)常服務(wù)連接數(shù)據(jù)庫報錯，第二天早上我收到了日志愈捅，主要的異常如下：

Caused by: com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 603,115 milliseconds ago.  The last packet sent successfully to the server was 603,115 milliseconds ago.
    at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174) ~[mysql-connector-java-8.0.16.jar!/:8.0.16]
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64) ~[mysql-connector-java-8.0.16.jar!/:8.0.16]
    at com.mysql.cj.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.java:634) ~[mysql-connector-java-8.0.16.jar!/:8.0.16]
    at com.mysql.cj.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement.java:414) ~[mysql-connector-java-8.0.16.jar!/:8.0.16]
    at com.mysql.cj.jdbc.ClientPreparedStatement.executeQuery(ClientPreparedStatement.java:1005) ~[mysql-connector-java-8.0.16.jar!/:8.0.16]
    at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52) ~[HikariCP-2.7.9.jar!/:na]
    at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java) ~[HikariCP-2.7.9.jar!/:na]
    at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.extract(ResultSetReturnImpl.java:60) ~[hibernate-core-5.2.17.Final.jar!/:5.2.17.Final]
    ... 149 common frames omitted

看到這樣的日志帐偎，大致分析思路是：

1. 是不是連接失活后依然嘗試重新連接導(dǎo)致的
2. 其他一些超時時間，設(shè)置的連接時間太短
3. 數(shù)據(jù)庫壓力太大
4. 網(wǎng)絡(luò)抖動

逐一排查

• 連接失活

這是比較常見的原因御雕，由于MySQL的 wait_timeout 小于應(yīng)用中連接池設(shè)置的連接存活時間矢沿，導(dǎo)致MySQL已經(jīng)將連接關(guān)閉回收了，而連接池中的連接仍然存在酸纲，當(dāng)應(yīng)用獲取到這個連接進(jìn)行數(shù)據(jù)庫操作時捣鲸，就會拋出類似上述的異常。

查看MySQL 的wait_timeout

show VARIABLES like '%timeout'

結(jié)果如下

connect_timeout 10
delayed_insert_timeout  300
have_statement_timeout  YES
innodb_flush_log_at_timeout 1
innodb_lock_wait_timeout    10
innodb_rollback_on_timeout  OFF
interactive_timeout 28800
lock_wait_timeout   31536000
net_read_timeout    30
net_write_timeout   60
rpl_semi_sync_master_timeout    10000
rpl_stop_slave_timeout  31536000
slave_net_timeout   60
wait_timeout    28800

發(fā)現(xiàn)wait_timeout 值已經(jīng)設(shè)置為28800 （8小時）闽坡， 而我的Hikari使用的是默認(rèn)配置栽惶，在com.zaxxer.hikari.HikariConfig 查看

public class HikariConfig implements HikariConfigMXBean
{
   ...
   private static final long CONNECTION_TIMEOUT = SECONDS.toMillis(30);
   private static final long VALIDATION_TIMEOUT = SECONDS.toMillis(5);
   private static final long IDLE_TIMEOUT = MINUTES.toMillis(10);
   private static final long MAX_LIFETIME = MINUTES.toMillis(30);
   private static final int DEFAULT_POOL_SIZE = 10;
   ...
}

可以看到默認(rèn)的存活時間 （MAX_LIFETIME）是30分鐘，小于8小時疾嗅，所有并不是連接失活導(dǎo)致的異常媒役。

• 其他超時時間分析

其實Hikari 設(shè)置的默認(rèn)時間一般還是比較合理的，比如連接超時時長30s宪迟，驗證連接有效性的超時時長是5s, 連接閑置超時時長是10min, 感覺也沒啥問題，應(yīng)用方面暫時沒有出路交惯，看看數(shù)據(jù)庫服務(wù)側(cè)是不是有突破口次泽。

• 數(shù)據(jù)庫壓力太大

服務(wù)側(cè)首先想到就是會不會連接不夠用了，于是回頭看了下應(yīng)用側(cè)應(yīng)用連接池配置的連接數(shù)席爽，

spring:
    ...
    datasource
        hikari:
            minimum-idle: 10
            maximum-pool-size: 100

應(yīng)用已經(jīng)配置了最大連接池為100意荤，在應(yīng)用日志中并沒有發(fā)現(xiàn)獲取連接超時等問題，服務(wù)端的最大連接數(shù)配置為3200只锻， 而發(fā)生異常的這段時間監(jiān)控MySQL的最大連接數(shù)還不過百玖像，也說明了連接池是完全夠用的。

似乎看到了曙光

這時候小伙伴告訴我 百度到有通過 在應(yīng)用添加 connection-test-query解決了問題齐饮。

spring:
    ...
    datasource
        hikari:
            minimum-idle: 10
            maximum-pool-size: 100
            connection-test-query: SELECT 1

我們嘗試也在應(yīng)用添加這個配置捐寥，不幸的是異常出現(xiàn)的頻率降低了笤昨，但仍然會出現(xiàn)！這個配置的作用是在連接池將連接交給jpa使用前校驗一下連接的可用性握恳，根據(jù)這個表現(xiàn)當(dāng)時已經(jīng)有了一些猜測瞒窒，可能是網(wǎng)絡(luò)抖動引起的。

為啥猜想是網(wǎng)絡(luò)抖動
connection-test-query 的使用： 在 com.zaxxer.hikari.pool.PoolBase.java 中

boolean isConnectionAlive(final Connection connection)
{
           ... 代碼省略
           // 設(shè)置校驗超時時間
           setNetworkTimeout(connection, validationTimeout);
           // isUseJdbc4Validation = config.getConnectionTestQuery() == null, 
           // 即如果沒配置connection-test-query, 直接使用connection.isValid驗證
           if (isUseJdbc4Validation) {
              return connection.isValid(validationSeconds);
           }
           ... 代碼省略
           // 執(zhí)行查詢語句進(jìn)行校驗
           statement.execute(config.getConnectionTestQuery());
           ... 代碼省略
  }

當(dāng)JPA 獲取連接時會調(diào)用com.zaxxer.hikari.pool.HikariPool.java的getConnection方法

public Connection getConnection(final long hardTimeout) throws SQLException {
       ... 代碼省略
       // 1. 被標(biāo)記為evicted, 關(guān)閉連接
       // 2. 如果上次訪問時間到現(xiàn)在超過 ALIVE_BYPASS_WINDOW_MS乡洼，需要檢測連接是否可用
       if (poolEntry.isMarkedEvicted() 
           || (elapsedMillis(poolEntry.lastAccessed, now) > ALIVE_BYPASS_WINDOW_MS
           && !isConnectionAlive(poolEntry.connection))) {
           closeConnection(poolEntry, poolEntry.isMarkedEvicted() ? >EVICTED_CONNECTION_MESSAGE : DEAD_CONNECTION_MESSAGE);
           timeout = hardTimeout - elapsedMillis(startTime);
       }
       ... 代碼省略
}

從代碼片段可以看出崇裁，獲取連接時會去判斷 上次訪問時間到現(xiàn)在的時間，如果這個時間小于ALIVE_BYPASS_WINDOW_MS（常量默認(rèn)值是500ms）束昵，則不會檢測連接有效性拔稳。假設(shè)是因為網(wǎng)絡(luò)抖動導(dǎo)致的異常，在頻繁操作數(shù)據(jù)庫時锹雏，JPA可能會在500ms內(nèi)多次拿取同一個連接巴比，假設(shè)第一次獲取連接時網(wǎng)絡(luò)正常，所以可以正常執(zhí)行數(shù)據(jù)庫操作逼侦，而當(dāng)?shù)诙文萌∵B接時：

• 如果在500ms以內(nèi)匿辩，則不會校驗有效性直接給JPA使用
• 如果在500ms外但沒有配置connection-test-query，也不會進(jìn)行請求校驗榛丢，這個過程中只要網(wǎng)絡(luò)發(fā)生抖動铲球，都可能造成jpa執(zhí)行失敗
• 如果配置了connection-test-query，因為500ms以外每次都會先連接數(shù)據(jù)庫校驗，一定程度上可以減少報錯的頻率。
  基于以上原因爸黄，推測本次異澄拖拢可能是網(wǎng)絡(luò)不穩(wěn)定導(dǎo)致；

雙向驗證

在驗證connection-test-query過程中该编，也排查了下數(shù)據(jù)庫日志，發(fā)現(xiàn)了大量的“Got an error reading communication packet” 警告，順騰摸瓜芍瑞，看到了Aborted clients或者Aborted connects的值

show status like 'Abort%';
----------------------------------------
Aborted_clients 17803532
Aborted_connects    20
----------------------------------------

發(fā)現(xiàn) 大量 Aborted_clients， 應(yīng)用程序使用連接池管理褐墅，也沒有出現(xiàn)程序死機等情況拆檬，可以排查是未正確關(guān)閉連接導(dǎo)致的，超時時間之前已經(jīng)確認(rèn)過妥凳，也可以排出竟贯，那么最可能就是網(wǎng)絡(luò)抖動導(dǎo)致客戶端意外中斷，兩相驗證逝钥，基本可以確定網(wǎng)絡(luò)問題屑那。

Aborted Connect
嘗試連接到MySQL服務(wù)器失敗的次數(shù)，增長原因：

• 沒有權(quán)限訪問數(shù)據(jù)庫；
• 密碼錯誤持际；
• 連接的數(shù)據(jù)包不合法沃琅；
• 超過連接時間限制，connect_timeout控制（mysql默認(rèn)是10s,一般不會超時）

Aborted Clients
客戶端沒有正確關(guān)閉連接而中止的連接數(shù);

• 客戶端程序在退出之前未正確關(guān)閉MySQL連接;
• 客戶端休眠的時間超過了系統(tǒng)變量wait_timeout和interactive_timeout的值选酗，導(dǎo)致連接被MySQL進(jìn)程終止;
• 客戶端程序在數(shù)據(jù)傳輸過程中突然結(jié)束;

問題解決

確定原因基本就解決了90%阵难，最后咨詢相關(guān)同事發(fā)現(xiàn)昨天恰好夜里公司DNS更新，為了防止類似問題再出現(xiàn)芒填，直接使用MySQL集群的VIP進(jìn)行訪問呜叫，目前沒有再出現(xiàn)問題。

總結(jié)：感慨一下殿衰，程序員的時間都去哪了朱庆，不知道你可有領(lǐng)悟，哈哈哈Ｃ葡椤Ｓ榧铡！