昨天夜里小伙伴上线新系统时，发现经常服务连接数据库报错，第二天早上我收到了日志，主要的异常如下：
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
看到这样的日志，大致分析思路是：
- 是不是连接失活后依然尝试重新连接导致的
- 其他一些超时时间，设置的连接时间太短
- 数据库压力太大
- 网络抖动
逐一排查
- 连接失活
这是比较常见的原因，由于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进行访问，目前没有再出现问题。
总结：感慨一下，程序员的时间都去哪了，不知道你可有领悟，哈哈哈！！！
