Mysql連接池 [ druid ] 的坑

Mysql無效鏈接異常：com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

背景分析

1、異常詳情：異常的意思是，前一次成功的使用連接是699,944毫秒以前，也就是大概11分鍾之前（空閑時間超過10分鍾）

2019-06-29 14:16:02:309|[DubboServerHandler-10.0.70.164:20880-thread-200]|[TID: N/A]|ERROR|com.alibaba.druid.pool.DruidDataSource|discard connection
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure

The last packet successfully received from the server was 699,944 milliseconds ago.  The last packet sent successfully to the server was 1 milliseconds ago.
    at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:590)
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:57)
    at com.mysql.cj.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:1983)
    at com.mysql.cj.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1826)
    at com.mysql.cj.jdbc.PreparedStatement.execute(PreparedStatement.java:1153)
    at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:493)
    at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:63)
    at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
    at org.apache.ibatis.executor.ReuseExecutor.doQuery(ReuseExecutor.java:60)
    at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:325)
    at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
    at com.github.pagehelper.PageInterceptor.executeAutoCount(PageInterceptor.java:201)
    at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:113)
    at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
    at com.sun.proxy.$Proxy178.query(Unknown Source)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:148)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:141)
    at sun.reflect.GeneratedMethodAccessor302.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:434)
    at com.sun.proxy.$Proxy83.selectList(Unknown Source)
    at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:231)
    at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:128)
    at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:68)
    at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:53)
    at com.sun.proxy.$Proxy115.selectList(Unknown Source)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
    at com.sun.proxy.$Proxy116.selectList(Unknown Source)
    at com.dd.rr.dao.impl.DemoDaoImpl.selectList(DemoDaoImpl.java:27)
    at com.dd.rr.dao.impl.DemoDaoImpl$$FastClassBySpringCGLIB$$31e4abe5.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)
    at com.dd.rr.dao.impl.DemoDaoImpl$$EnhancerBySpringCGLIB$$ea760753.selectList(<generated>)
    at com.dd.rr.service.impl.DemoServiceImpl.selectPageList(DemoServiceImpl.java:69)
    at com.alibaba.dubbo.common.bytecode.Wrapper45.invokeMethod(Wrapper45.java)
    at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47)
    at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:76)
    at com.alibaba.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:52)
    at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56)
    at com.dd.rr.filter.ParamValidationFilter.invoke(ParamValidationFilter.java:93)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.dd.rr.filter.LogFilter.invoke(LogFilter.java:43)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:62)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:72)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:131)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)
    at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)
    at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:103)
    at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:96)
    at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:172)
    at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51)
    at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:80)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
Caused by: com.mysql.cj.core.exceptions.CJCommunicationsException: Communications link failure

The last packet successfully received from the server was 699,944 milliseconds ago.  The last packet sent successfully to the server was 1 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.cj.core.exceptions.ExceptionFactory.createException(ExceptionFactory.java:54)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createException(ExceptionFactory.java:93)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createException(ExceptionFactory.java:133)
    at com.mysql.cj.core.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:149)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.readPacket(MysqlaProtocol.java:527)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.checkErrorPacket(MysqlaProtocol.java:723)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.sendCommand(MysqlaProtocol.java:662)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.sqlQueryDirect(MysqlaProtocol.java:950)
    at com.mysql.cj.mysqla.MysqlaSession.sqlQueryDirect(MysqlaSession.java:431)
    at com.mysql.cj.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:1978)
    ... 79 common frames omitted
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.cj.core.io.FullReadInputStream.readFully(FullReadInputStream.java:61)
    at com.mysql.cj.mysqla.io.SimplePacketReader.readHeader(SimplePacketReader.java:60)
    at com.mysql.cj.mysqla.io.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:48)
    at com.mysql.cj.mysqla.io.MultiPacketReader.readHeader(MultiPacketReader.java:51)
    at com.mysql.cj.mysqla.io.MysqlaProtocol.readPacket(MysqlaProtocol.java:521)
    ... 84 common frames omitted

2、優化前：代碼中數據庫連接池的配置如下：

    #配置初始化大小、最小、最大
    maxActive: 20   # 連接池最大活躍連接數
    initialSize: 1      # 初始化連接池的連接數
    minIdle: 3         # 空閑鏈接保持數量
    maxWait: 60000    # 最大的響應等待時間，單位毫秒
    time-between-eviction-runs-millis: 60000   # 
    minEvictableIdleTimeMillis: 300000
    test-while-idle: true   #指明連接是否被空閑連接回收器(如果有)進行檢驗.如果檢測失敗,則連接將被從池中去除.注意: 設置為true后如果要生效,validationQuery參數必須設置為非空字符串
    test-on-borrow: false   # 指明是否在從池中取出連接前進行檢驗,如果檢驗失敗,則從池中去除連接並嘗試取出另一個.注意: 設置為true后如果要生效,validationQuery參數必須設置為非空字符串
    test-on-return: false    # 指明是否在歸還到池中前進行檢驗 注意: 設置為true后如果要生效,validationQuery參數必須設置為非空字符串

很顯然可以看出，雖然配置了 test-while-idle: true，但是沒有配置 validationQuery，所示實際是未生效的；

3、優化前：數據庫執行 show variables like '%timeout%' 查看mysql數據庫中的超時屬性配置（如下圖所示），當連接空閑十分鍾后，數據庫會主動斷開連接；

結合以上三點情況，可以分析出：

首先，線程池一直空閑，至少也會維持3個空閑鏈接，由於沒有鏈接有效性檢測，當空閑超時10分鍾后，被mysql服務端主動斷開連接；

而此時，連接池保持的空閑鏈接就是無效鏈接，此時在執行sql必然出現Communications link failure異常

解決方案：

在鏈接池中新增參數validationQuery:select 1 from dural，讓配置test-while-idle: true  生效；

如果考慮系統穩定性最好也啟用配置：test-on-borrow: true，取鏈接時，先檢測一下，然后在使用；

后續深入研究后：在做詳細說明；

附錄1 springBoot配置線程池的yuml配置

spring:
  datasource:
#   數據源基本配置
    username: root
    password: root
    driver-class-name: com.mysql.jdbc.Driver
    url: jdbc:mysql://localhost:3306/duid
    type: com.alibaba.druid.pool.DruidDataSource
#   數據源其他配置
    initialSize: 5
    minIdle: 5
    maxActive: 20
    maxWait: 60000
    timeBetweenEvictionRunsMillis: 60000
    minEvictableIdleTimeMillis: 300000
    validationQuery: SELECT 1 FROM DUAL
    testWhileIdle: true
    testOnBorrow: false
    testOnReturn: false
    poolPreparedStatements: true
#   配置監控統計攔截的filters，去掉后監控界面sql無法統計，'wall'用於防火牆  
    filters: stat,wall
    maxPoolPreparedStatementPerConnectionSize: 20
    useGlobalDataSourceStat: true  
    connectionProperties: druid.stat.mergeSql=true;druid.stat.slowSqlMillis=500

 

參考文章：

1、使用druid連接池帶來的坑testOnBorrow=false

2、springboot配置druid數據源