使用MYSQL做为数据库项目中出现的异常: Communications link failure 二种场景的问题解析

曾经终败给现在 2022-04-10 04:20 1390阅读 0赞

**在一次版本线上慢查询事件中,发现大量的Communications link failure 异常**

我将这种异常分为二类:

1.低于120秒,莫名原因导致 mysql server端强杀

2.超过120秒(公司设定mysql server端120秒强杀)

项目采用的数据层分库分表的技术组件:  
当当网的ShardingJdbc

问题场景复现及解决方案

1.低于120秒,莫名原因导致 mysql server端强杀

本地复盘

**按照线上的情况,使用了shardingJdbc的shardingApi(当前有128库,就会并行128个线程去执行),查询返回结果集总和大于几万的数据,并且此API是在进程中并发较高,在本机使用了3个线程,然后使用线程池(最高3个,实际需要执行的就是3\*128=384个线程),死循环的不断运行,没过多久,在业务日志中就出现大量的Communications link failure,具体异常堆栈如下:**

> \[2018-05-02 02:09:30.014\] \[WARN\] \[ShardingJDBC-2\] \[com.xxx.yyyyy.zzzzzz.pool.ProxyConnection\] >>> node\_10 - Connection com.mysql.jdbc.JDBC4Connection@46e7894e marked as broken because of SQLSTATE(08S01), ErrorCode(0)  
> com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> 
> The last packet successfully received from the server was 34 milliseconds ago.  The last packet sent successfully to the server was 6,481 milliseconds ago.  
>         at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)  
>         at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)  
>         at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)  
>         at java.lang.reflect.Constructor.newInstance(Constructor.java:423)  
>         at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)  
>         at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)  
>         at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2229)  
>         at com.mysql.jdbc.MysqlIO.nextRow(MysqlIO.java:1989)  
>         at com.mysql.jdbc.MysqlIO.readSingleRowSet(MysqlIO.java:3410)  
>         at com.mysql.jdbc.MysqlIO.getResultSet(MysqlIO.java:470)  
>         at com.mysql.jdbc.MysqlIO.readResultsForQueryOrUpdate(MysqlIO.java:3112)  
>         at com.mysql.jdbc.MysqlIO.readAllResults(MysqlIO.java:2341)  
>         at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2736)  
>         at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2494)  
>         at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)  
>         at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)  
>         at com.xxx.yyyyy.zzzzzz.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:36)  
>         at com.xxx.yyyyy.zzzzzz.pool.CaelusProxyPreparedStatement.executeQuery(CaelusProxyPreparedStatement.java)  
>         at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.executeQueryInternal(PreparedStatementExecutor.java:89)  
>         at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.access$000(PreparedStatementExecutor.java:39)  
>         at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor$1.execute(PreparedStatementExecutor.java:73)  
>         at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor$1.execute(PreparedStatementExecutor.java:68)  
>         at com.dangdang.ddframe.rdb.sharding.executor.ExecutorEngine$1.call(ExecutorEngine.java:114)  
>         at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)  
>         at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)  
>         at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)  
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)  
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  
>         at java.lang.Thread.run(Thread.java:745)  
> Caused by: java.io.EOFException: Can not read response from server. Expected to read 6 bytes, read 2 bytes before connection was unexpectedly lost.  
>         at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)  
>         at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:2212)  
>         ... 22 common frames omitted

**在云主机的mysql server端的error日志也对应的出现大量的Got an error reading communication packets和Got timeout writing communication packets 信息(xxx为规避公司安全信息内容）**

> 2018-04-28T02:29:00.358697Z 6217 \[Note\] Aborted connection 6217 to db: 'xxx\_006' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.358720Z 6235 \[Note\] Aborted connection 6235 to db: 'xxx\_001' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.359237Z 6232 \[Note\] Aborted connection 6232 to db: 'xxx\_001' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.359242Z 6215 \[Note\] Aborted connection 6215 to db: xxx\_030' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.359656Z 6251 \[Note\] Aborted connection 6251 to db: 'xxx\_018' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.360229Z 6234 \[Note\] Aborted connection 6234 to db: 'xxx\_005' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.360271Z 6233 \[Note\] Aborted connection 6233 to db: 'xxx\_028' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.360572Z 6241 \[Note\] Aborted connection 6241 to db: 'xxx\_009' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.361019Z 6214 \[Note\] Aborted connection 6214 to db: 'xxx\_025' user: 'xxx' host: '10.100.69.231' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.361023Z 6195 \[Note\] Aborted connection 6195 to db: 'xxx\_031' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.358721Z 6250 \[Note\] Aborted connection 6250 to db: 'xxx\_027' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.343058Z 6193 \[Note\] Aborted connection 6193 to db: 'xxx\_013' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:29:00.361708Z 6225 \[Note\] Aborted connection 6225 to db: 'xxx\_011' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got an error reading communication packets)  
> 2018-04-28T02:32:09.956824Z 6797 \[Note\] Aborted connection 6797 to db: 'xxx\_016' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout writing communication packets)  
> 2018-04-28T02:32:10.071781Z 6800 \[Note\] Aborted connection 6800 to db: 'xxx\_012' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout writing communication packets)  
> 2018-04-28T02:32:10.073718Z 6798 \[Note\] Aborted connection 6798 to db: 'xxx\_007' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout writing communication packets)

初步猜测 此异常是有关联的,根据mysql异常在网上搜索了一下

大致与mysql 配置的以下三个参数有关(此参数线上和云主机的数据库是一致的)

net\_read\_timeout=3

net\_write\_timeout=6

net\_retry\_count=2

附上参数说明:

net\_read\_timeout ：数据读取超时时间。在终止读之前，从一个连接获得数据而等待的时间秒数；当服务正在从客户端读取数据时，net\_read\_timeout控制何时超时。即客户端执行数据读取，等待多少秒仍未执行成功时自动断开连接。

net\_write\_timeout：数据库写超时时间。和net\_read\_timeout意义类似，在终止写之前，等待多少秒把block写到连接；当服务正在写数据到客户端时，net\_write\_timeout控制何时超时。

同时也看了一篇关于mysql源码文章(可以直接看重点:3、调用vio虚拟I/O接口进行读取阶段)

[http://blog.itpub.net/7728585/viewspace-2138631/][http_blog.itpub.net_7728585_viewspace-2138631]

那么根据问题,尝试调整mysql server端的参数为

net\_read\_timeout=10

net\_write\_timeout=10

net\_retry\_count=5

再次运行本地复盘的程序,mysql服务端的error信息 有关Got an error reading communication packets和Got timeout writing communication packets 信息已消失,java应用日志中的低于120秒的Communications link failure 也消失了

总结:

修改mysqlserver端虽然可以解决问题,但本质还是在于程序上无止境的并行和大量读写操作,随着程序员无休止的增加并行,mysql server端不可能无脑的调整参数,就算去调了,可能会引发mysql server各种不稳定,那么在程序上就要进行限流,做到每个程序进程中的线程可控,分布式上整体的并行可控,程序上的SQL返回结果集大小控制在合理,控制不了继续拆解.

2.超过120秒(公司设定mysql server端120秒强杀)

此超过120秒的Communications link failure,是在解决完上面第1个问题,还残留的问题,但并不是同一个问题,我们都知道120秒,是公司在mysql server端定的一个标准wait\_timeout 时间,过了这个120秒,服务端就无脑的强杀了闲置的连接,这个一般都在连接池的配置上,可以规避.

但我这边碰到的问题,其实已经有配连接池策略,但还是发生了,那么就说明,一定在程序中有连接被获取后,闲置了120秒以上再使用它,连接池caelus是可以排除的(这在无数的实践中都有证明,连接池在连接管理是稳定的),那么剩下的就只有ShardingJdbc和程序上不合理的代码了

但查看线上业务日志,此问题发生在不同的作业,那么问题肯定就在公共的代码中了

本地复盘

**直接使用问题1的代码方式,既可重现,在执行程序后2到3分钟后,就开始出现120秒以上的Communications link failure,具体异常堆栈如下:**

> 五月 01, 2018 10:21:37 下午 com.google.common.util.concurrent.AggregateFuture$RunningState handleException  
> 严重: Got more than one input Future failure. Logging failures after the first  
> com.dangdang.ddframe.rdb.sharding.exception.ShardingJdbcException: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> 
> The last packet successfully received from the server was 143,759 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.  
>     at com.dangdang.ddframe.rdb.sharding.executor.ExecutorExceptionHandler.handleException(ExecutorExceptionHandler.java:61)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.executeQueryInternal(PreparedStatementExecutor.java:92)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.access$000(PreparedStatementExecutor.java:39)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor$1.execute(PreparedStatementExecutor.java:73)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor$1.execute(PreparedStatementExecutor.java:68)  
>     at com.dangdang.ddframe.rdb.sharding.executor.ExecutorEngine$1.call(ExecutorEngine.java:114)  
>     at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)  
>     at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)  
>     at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)  
>     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)  
>     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  
>     at java.lang.Thread.run(Thread.java:745)  
> Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure
> 
> The last packet successfully received from the server was 143,759 milliseconds ago.  The last packet sent successfully to the server was 0 milliseconds ago.  
>     at sun.reflect.GeneratedConstructorAccessor47.newInstance(Unknown Source)  
>     at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)  
>     at java.lang.reflect.Constructor.newInstance(Constructor.java:423)  
>     at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)  
>     at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:989)  
>     at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3559)  
>     at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)  
>     at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)  
>     at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)  
>     at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)  
>     at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2494)  
>     at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)  
>     at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966)  
>     at com.xxx.yyyyy.zzzzzz.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:36)  
>     at com.xxx.yyyyy.zzzzzz.pool.CaelusProxyPreparedStatement.executeQuery(CaelusProxyPreparedStatement.java)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.executeQueryInternal(PreparedStatementExecutor.java:89)  
>     ... 10 more  
> Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.  
>     at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011)  
>     at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)  
>     ... 20 more
> 
> 五月 01, 2018 10:21:37 下午 com.google.common.util.concurrent.AggregateFuture$RunningState handleException  
> 严重: Got more than one input Future failure. Logging failures after the first  
> com.dangdang.ddframe.rdb.sharding.exception.ShardingJdbcException: java.sql.SQLException: No operations allowed after statement closed.  
>     at com.dangdang.ddframe.rdb.sharding.executor.ExecutorExceptionHandler.handleException(ExecutorExceptionHandler.java:61)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.executeQueryInternal(PreparedStatementExecutor.java:92)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.access$000(PreparedStatementExecutor.java:39)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor$1.execute(PreparedStatementExecutor.java:73)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor$1.execute(PreparedStatementExecutor.java:68)  
>     at com.dangdang.ddframe.rdb.sharding.executor.ExecutorEngine$1.call(ExecutorEngine.java:114)  
>     at com.google.common.util.concurrent.TrustedListenableFutureTask$TrustedFutureInterruptibleTask.runInterruptibly(TrustedListenableFutureTask.java:111)  
>     at com.google.common.util.concurrent.InterruptibleTask.run(InterruptibleTask.java:58)  
>     at com.google.common.util.concurrent.TrustedListenableFutureTask.run(TrustedListenableFutureTask.java:75)  
>     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)  
>     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)  
>     at java.lang.Thread.run(Thread.java:745)  
> Caused by: java.sql.SQLException: No operations allowed after statement closed.  
>     at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:964)  
>     at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:897)  
>     at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:886)  
>     at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:860)  
>     at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:442)  
>     at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1919)  
>     at com.xxx.yyyyy.zzzzzz.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:36)  
>     at com.xxx.yyyyy.zzzzzz.pool.CaelusProxyPreparedStatement.executeQuery(CaelusProxyPreparedStatement.java)  
>     at com.dangdang.ddframe.rdb.sharding.executor.PreparedStatementExecutor.executeQueryInternal(PreparedStatementExecutor.java:89)  
>     ... 10 more

**在mysql server端的error日志也对应的大量的Got timeout reading communication packets 信息(xxx为规避公司安全信息内容）**

> 2018-04-28T00:21:11.006811Z 6605 \[Note\] Aborted connection 6605 to db: 'xxx\_005' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:24:43.600432Z 6607 \[Note\] Aborted connection 6607 to db: 'xxx\_026' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:29:46.082047Z 6609 \[Note\] Aborted connection 6609 to db: 'xxx\_023' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:33:19.703812Z 6610 \[Note\] Aborted connection 6610 to db: 'xxx\_017' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:36:49.871118Z 6612 \[Note\] Aborted connection 6612 to db: 'xxx\_003' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:40:20.465173Z 6614 \[Note\] Aborted connection 6614 to db: 'xxx\_024' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:45:20.750288Z 6616 \[Note\] Aborted connection 6616 to db: 'xxx\_009' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:50:22.095151Z 6618 \[Note\] Aborted connection 6618 to db: 'xxx\_000' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:53:52.137204Z 6620 \[Note\] Aborted connection 6620 to db: 'xxx\_009' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T00:57:22.688387Z 6621 \[Note\] Aborted connection 6621 to db: 'xxx\_021' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T01:04:29.575128Z 6625 \[Note\] Aborted connection 6625 to db: 'xxx\_026' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T01:09:29.641212Z 6627 \[Note\] Aborted connection 6627 to db: 'xxx\_024' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)  
> 2018-04-28T01:12:59.751070Z 6628 \[Note\] Aborted connection 6628 to db: 'xxx\_014' user: 'xxx' host: 'xxx.xxx.xxx.xxx' (Got timeout reading communication packets)

有了这些日志,首先看mysql端的日志,此Got timeout reading communication packets 平时也是持续稳定的输出,并不是因为程序出现问题才出现,可以得出,此是服务端在wait\_timeout 配置的时间到了,强杀的对应日志,所以意义不大.

随后查看业务日志的异常堆栈,可以看出ShardingJdbc使用了线程池,然后根据堆栈查看源代码,发现ShardingJdbc在处理多线程归并逻辑时,是先产生获取连接的动作,再多线程去执行连接的Statement ,那么问题就来了,ShardingJdbc默认设定的是100的最大并行数,如果需要处理超过或者本机CPU较慢时,线程池就会排队,线程池在具体线程还没有运行前的connection就已经开始闲置,随时时间的推移,陆陆续续产生超过120秒的Communications link failure

附上查看ShardingJdbc关键源代码,大家可以通过上面的异常堆栈及下面的源代码互相对应

以下二段源代码,顺序也是执行的前后顺序

在ShardingPreparedStatement 167行已经开始产生连接  
对应的类:

> com\\dangdang\\sharding-jdbc-core\\1.4.2\\sharding-jdbc-core-1.4.2.jar!\\com\\dangdang\\ddframe\\rdb\\sharding\\jdbc\\ShardingPreparedStatement.class   
> 对应的行:PreparedStatement preparedStatement = (PreparedStatement) getStatement(getShardingConnection().getConnection(each.getDataSource(), sqlRouteResult.getSqlStatementType()), each.getSql());

在ExecutorEngine 110行已经开始多线程运行

> com\\dangdang\\sharding-jdbc-core\\1.4.2\\sharding-jdbc-core-1.4.2.jar!\\com\\dangdang\\ddframe\\rdb\\sharding\\executor\\ExecutorEngine.class  
> result.add(executorService.submit(new Callable<O>() \{  
>       
>     @Override  
>     public O call() throws Exception \{  
>         return executeUnit.execute(each);  
>     \}  
> \}));

如上可以看到如果按这样的玩法,再结合单进程内多线程的超越本机能力的并行,就会间断性的产生超过120秒的Communications link failure

总结:

按我的理解,这个应该算是ShardingJdbc的BUG

vipshop\_ebs/朱杰

2018-12-24

[http_blog.itpub.net_7728585_viewspace-2138631]: http://blog.itpub.net/7728585/viewspace-2138631/