• date: 2018-04-19 21:00
• tag: java,mysql,exception,mat,调试,jvm
• 工具: gceasy.io, MAT

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

• 分析:

1. 通过日志确认系统在一天前就已经停止运行
2. 代码较简单应该不存在DB写入操作死锁
3. mysql操作不是特别频繁

• 定位:

1. 使用jmap -dump导出线上的应用的heap dump
2. jstack 导出堆栈信息
3. 分析jstack发现多个Thread在DB写入时在等待同一把锁
4. 通过MAT分析dump
5. 通过OQL在MAT中定位上面出现的锁住多个Thread的锁对象
6. 通过分析发现锁对象的所有者是阿里druid线程池的com.alibaba.druid.pool.DruidDataSource
7. 在IDE中查看DruidDataSource的源码发现几个关键属性: poolingCount, errorCount, destroyCount, lastError
8. google搜索lastError的描述Communications link failure, 得到可能是网络原因导致的mysql连接关闭
9. 在MAT中查看poolingCount, errorCount, destroyCount属性的值发现与上述结论一致
10. 重启应用，问题消失

• 思考:

1. 为什么Druid线程池没有尝试重新连接?
2. 需要优化日志，提高排查效率
3. 增加必要的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(<generated>) ~[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(<generated>) ~[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]