date: 2018-04-19 21:00
tag: java,mysql,exception,mat,调试,jvm
工具: gceasy.io, mat
线上系统出现一个诡异的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]