昨天夜里小伙伴上线新系统时，发现经常服务连接数据库报错，第二天早上我收到了日志，主要的异常如下：

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. 是不是连接失活后依然尝试重新连接导致的
2. 其他一些超时时间，设置的连接时间太短
3. 数据库压力太大
4. 网络抖动

逐一排查

• 连接失活

这是比较常见的原因，由于MySQL的 wait_timeout 小于应用中连接池设置的连接存活时间，导致MySQL已经将连接关闭回收了，而连接池中的连接仍然存在，当应用获取到这个连接进行数据库操作时，就会抛出类似上述的异常。

查看MySQL 的wait_timeout

show VARIABLES like '%timeout'

结果如下

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

发现wait_timeout 值已经设置为28800 （8小时）， 而我的Hikari使用的是默认配置，在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;
   ...
}

可以看到默认的存活时间 （MAX_LIFETIME）是30分钟，小于8小时，所有并不是连接失活导致的异常。

• 其他超时时间分析

其实Hikari 设置的默认时间一般还是比较合理的，比如连接超时时长30s，验证连接有效性的超时时长是5s, 连接闲置超时时长是10min, 感觉也没啥问题，应用方面暂时没有出路，看看数据库服务侧是不是有突破口。

• 数据库压力太大

服务侧首先想到就是会不会连接不够用了，于是回头看了下应用侧应用连接池配置的连接数，

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

应用已经配置了最大连接池为100，在应用日志中并没有发现获取连接超时等问题，服务端的最大连接数配置为3200， 而发生异常的这段时间监控MySQL的最大连接数还不过百，也说明了连接池是完全够用的。

似乎看到了曙光

这时候小伙伴告诉我 百度到有通过 在应用添加 connection-test-query解决了问题。

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

我们尝试也在应用添加这个配置，不幸的是异常出现的频率降低了，但仍然会出现！这个配置的作用是在连接池将连接交给jpa使用前校验一下连接的可用性，根据这个表现当时已经有了一些猜测，可能是网络抖动引起的。

为啥猜想是网络抖动
connection-test-query 的使用： 在 com.zaxxer.hikari.pool.PoolBase.java 中

boolean isConnectionAlive(final Connection connection)
{
           ... 代码省略
           // 设置校验超时时间
           setNetworkTimeout(connection, validationTimeout);
           // isUseJdbc4Validation = config.getConnectionTestQuery() == null, 
           // 即如果没配置connection-test-query, 直接使用connection.isValid验证
           if (isUseJdbc4Validation) {
              return connection.isValid(validationSeconds);
           }
           ... 代码省略
           // 执行查询语句进行校验
           statement.execute(config.getConnectionTestQuery());
           ... 代码省略
  }

当JPA 获取连接时会调用com.zaxxer.hikari.pool.HikariPool.java的getConnection方法

public Connection getConnection(final long hardTimeout) throws SQLException {
       ... 代码省略
       // 1. 被标记为evicted, 关闭连接
       // 2. 如果上次访问时间到现在超过 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);
       }
       ... 代码省略
}

从代码片段可以看出，获取连接时会去判断 上次访问时间到现在的时间，如果这个时间小于ALIVE_BYPASS_WINDOW_MS（常量默认值是500ms），则不会检测连接有效性。假设是因为网络抖动导致的异常，在频繁操作数据库时，JPA可能会在500ms内多次拿取同一个连接，假设第一次获取连接时网络正常，所以可以正常执行数据库操作，而当第二次拿取连接时：

• 如果在500ms以内，则不会校验有效性直接给JPA使用
• 如果在500ms外但没有配置connection-test-query，也不会进行请求校验，这个过程中只要网络发生抖动，都可能造成jpa执行失败
• 如果配置了connection-test-query，因为500ms以外每次都会先连接数据库校验，一定程度上可以减少报错的频率。
  基于以上原因，推测本次异常可能是网络不稳定导致；

双向验证

在验证connection-test-query过程中，也排查了下数据库日志，发现了大量的“Got an error reading communication packet” 警告，顺腾摸瓜，看到了Aborted clients或者Aborted connects的值

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

发现 大量 Aborted_clients， 应用程序使用连接池管理，也没有出现程序死机等情况，可以排查是未正确关闭连接导致的，超时时间之前已经确认过，也可以排出，那么最可能就是网络抖动导致客户端意外中断，两相验证，基本可以确定网络问题。

Aborted Connect
尝试连接到MySQL服务器失败的次数，增长原因：

• 没有权限访问数据库；
• 密码错误；
• 连接的数据包不合法；
• 超过连接时间限制，connect_timeout控制（mysql默认是10s,一般不会超时）

Aborted Clients
客户端没有正确关闭连接而中止的连接数;

• 客户端程序在退出之前未正确关闭MySQL连接;
• 客户端休眠的时间超过了系统变量wait_timeout和interactive_timeout的值，导致连接被MySQL进程终止;
• 客户端程序在数据传输过程中突然结束;

问题解决

确定原因基本就解决了90%，最后咨询相关同事发现昨天恰好夜里公司DNS更新，为了防止类似问题再出现，直接使用MySQL集群的VIP进行访问，目前没有再出现问题。

总结：感慨一下，程序员的时间都去哪了，不知道你可有领悟，哈哈哈！！！