date: 2018-04-19 21:00

tag: java,mysql,exception,mat,调试,jvm

线上系统出现一个诡异的bug，通过heap dump分析

分析:

通过日志确认系统在一天前就已经停止运行

代码较简单应该不存在DB写入操作死锁

mysql操作不是特别频繁

定位:

使用jmap -dump导出线上的应用的heap dump

jstack 导出堆栈信息

分析jstack发现多个Thread在DB写入时在等待同一把锁

通过MAT分析dump

通过OQL在MAT中定位上面出现的锁住多个Thread的锁对象

通过分析发现锁对象的所有者是阿里druid线程池的com.alibaba.druid.pool.DruidDataSource

在IDE中查看DruidDataSource的源码发现几个关键属性: poolingCount, errorCount, destroyCount, lastError

google搜索lastError的描述Communications link failure, 得到可能是网络原因导致的mysql连接关闭

在MAT中查看poolingCount, errorCount, destroyCount属性的值发现与上述结论一致

重启应用，问题消失

思考:

为什么Druid线程池没有尝试重新连接?

需要优化日志，提高排查效率

增加必要的Metric和预警规则

程序假死时的heap dump:

OQL:

SELECT s.poolingCount,

s.errorCount.toString() AS errorCount,

s.destroyCount.toString() AS destroyCount,

s.createCount.toString() AS createCount,

s.lastError.exceptionMessage.toString()

FROM com.alibaba.druid.pool.DruidDataSource s

结果:

s.poolingCount |errorCount|destroyCount|createCount|s.lastError.exceptionMessage.toString()

---------------------------------------------------------------------------------------------------------------------------------------------

0 |10 |7 |17 |Communications link failure\u000a\u000aLast packet sent to the server was 180289 ms ago.

---------------------------------------------------------------------------------------------------------------------------------------------

s.connections:

结果:

Type|Name|Value

---------------

ref |[0] |null

ref |[1] |null

ref |[2] |null

ref |[3] |null

ref |[4] |null

ref |[5] |null

ref |[6] |null

ref |[7] |null

---------------

正常运行时候的core dump:

OQL:

SELECT s.poolingCount,

s.errorCount.toString() AS errorCount,

s.destroyCount.toString() AS destroyCount,

s.createCount.toString() AS createCount,

s.lastError.exceptionMessage.toString()

FROM com.alibaba.druid.pool.DruidDataSource s

结果:

s.poolingCount |errorCount|destroyCount|createCount|s.lastError.exceptionMessage.toString()

--------------------------------------------------------------------------------------------

1 |1 |0 |4 |

--------------------------------------------------------------------------------------------

s.connections:

结果:

Type|Name|Value

-------------------------------------------------------------------

ref |[0] |com.alibaba.druid.pool.DruidConnectionHolder @ 0xc5fb1958

ref |[1] |null

ref |[2] |null

ref |[3] |null

ref |[4] |null

ref |[5] |null

ref |[6] |null

ref |[7] |null

-------------------------------------------------------------------

日志文件中的异常堆栈:

org.springframework.dao.RecoverableDataAccessException:

### Error querying database. Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

Last packet sent to the server was 655505 ms ago.

### The error may exist in class path resource [mapper/ConfigMapper.xml]

### The error may involve com.myserver1.crawler.dao.ConfigDao.selectAllByType-Inline

### The error occurred while setting parameters

### SQL: select id, type, props, content, status, create_time, update_time from config where type = ? and status = 1

### Cause: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

Last packet sent to the server was 655505 ms ago.

; SQL []; Communications link failure

Last packet sent to the server was 655505 ms ago.; nested exception is com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

Last packet sent to the server was 655505 ms ago.

at org.springframework.jdbc.support.SQLExceptionSubclassTranslator.doTranslate(SQLExceptionSubclassTranslator.java:98) ~[spring-jdbc-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73) ~[spring-jdbc-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:81) ~[spring-jdbc-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.mybatis.spring.MyBatisExceptionTranslator.translateExceptionIfPossible(MyBatisExceptionTranslator.java:74) ~[mybatis-spring-1.2.3.jar!/:1.2.3]

at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:399) ~[mybatis-spring-1.2.3.jar!/:1.2.3]

at com.sun.proxy.$Proxy60.selectList(Unknown Source) ~[?:?]

at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:205) ~[mybatis-spring-1.2.3.jar!/:1.2.3]

at com.myserver1.crawler.dao.ConfigDao.selectAllByType(ConfigDao.java:27) ~[classes!/:1.0-SNAPSHOT]

at com.myserver1.crawler.dao.ConfigDao$$FastClassBySpringCGLIB$$98d41dde.invoke() ~[classes!/:1.0-SNAPSHOT]

at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204) ~[spring-core-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:721) ~[spring-aop-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157) ~[spring-aop-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136) ~[spring-tx-4.3.6.RELEASE.jar!/:4.3.6.RELEAS

E]

at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) ~[spring-aop-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:656) ~[spring-aop-4.3.6.RELEASE.jar!/:4.3.6.RELEASE]

at com.myserver1.crawler.dao.ConfigDao$$EnhancerBySpringCGLIB$$c890af99.selectAllByType() ~[classes!/:1.0-SNAPSHOT]

at com.myserver1.event.VideoItemListener.post(VideoItemListener.java:32) ~[classes!/:1.0-SNAPSHOT]

at com.myserver1.event.EventBus.push(EventBus.java:28) [classes!/:1.0-SNAPSHOT]

at com.myserver1.crawler.site.ABreadthCrawler.start(ABreadthCrawler.java:97) [classes!/:1.0-SNAPSHOT]

at com.myserver1.event.QueueThread.run(QueueThread.java:41) [classes!/:1.0-SNAPSHOT]

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

Last packet sent to the server was 655505 ms ago.

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:1.8.0_101]

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:1.8.0_101]

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:1.8.0_101]

at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:1.8.0_101]

at com.mysql.jdbc.Util.handleNewInstance(Util.java:406) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1074) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3246) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1917) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:995) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:477) ~[druid-0.2.9.jar!/:0.2.9]

at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:62) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:78) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:102) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:120) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:113) ~[mybatis-3.3.0.jar!/:3.3.0]

at sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]

at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_101]

at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:386) ~[mybatis-spring-1.2.3.jar!/:1.2.3]

... 15 more

Caused by: java.net.SocketException: Connection reset

at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113) ~[?:1.8.0_101]

at java.net.SocketOutputStream.write(SocketOutputStream.java:153) ~[?:1.8.0_101]

at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) ~[?:1.8.0_101]

at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) ~[?:1.8.0_101]

at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3227) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1917) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:995) ~[mysql-connector-java-5.1.6.jar!/:?]

at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:477) ~[druid-0.2.9.jar!/:0.2.9]

at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:62) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:78) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:62) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:303) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:154) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:102) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:82) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:120) ~[mybatis-3.3.0.jar!/:3.3.0]

at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:113) ~[mybatis-3.3.0.jar!/:3.3.0]

at sun.reflect.GeneratedMethodAccessor81.invoke(Unknown Source) ~[?:?]

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_101]