记一次线上宕机事件

今天同事反馈线上的一个中间件宕机了，进程没挂，但是已经不响应请求了，看后台日志也没有异常输出。

用jstack导出该服务的堆栈信息查看具体原因，发现很多线程都一直卡在SocketInputStream.socketRead0这里了，没有释放

"http-nio-8210-exec-5" #34 daemon prio=5 os_prio=0 tid=0x00007fcc662bb000 nid=0x75f runnable [0x00007fcbe19b4000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174) - locked <0x00000000e63c6880> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3472) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3903) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2530) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2683) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486) - locked <0x00000000e63d0c18> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858) - locked <0x00000000e63d0c18> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966) - locked <0x00000000e63d0c18> (a com.mysql.jdbc.JDBC4Connection) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) at org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:698) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:639) at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:690) at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:717) at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:767) at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.query(NamedParameterJdbcTemplate.java:192) at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.queryForList(NamedParameterJdbcTemplate.java:264) at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.queryForList(NamedParameterJdbcTemplate.java:271)

该服务是用了dbcp做动态数据源。推测是一些慢查询或死锁把dbcp的连接池占满了，后面请求再来想获取connection时，判断有连接失效了，就执行StatementImpl.close，但是这个连接还在其他线程执行sql被锁了，就会一直阻塞在.PreparedStatement.realClose等待获取锁，如下：

"http-nio-8210-exec-8" #37 daemon prio=5 os_prio=0 tid=0x00007fcc663ae800 nid=0x762 waiting for monitor entry [0x00007fcbe16b2000] java.lang.Thread.State: BLOCKED (on object monitor) at com.mysql.jdbc.PreparedStatement.realClose(PreparedStatement.java:2697) - waiting to lock <0x00000000e63d0c18> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.StatementImpl.close(StatementImpl.java:538) at org.apache.commons.dbcp.DelegatingStatement.close(DelegatingStatement.java:168) at org.apache.commons.dbcp.DelegatingConnection.passivate(DelegatingConnection.java:426) at org.apache.commons.dbcp.DelegatingConnection.close(DelegatingConnection.java:246) at org.apache.commons.dbcp.PoolableConnection.reallyClose(PoolableConnection.java:122) at org.apache.commons.dbcp.PoolableConnectionFactory.destroyObject(PoolableConnectionFactory.java:628) at org.apache.commons.pool.impl.GenericObjectPool.invalidateObject(GenericObjectPool.java:1290) at org.apache.commons.dbcp.AbandonedObjectPool.invalidateObject(AbandonedObjectPool.java:125) at org.apache.commons.dbcp.AbandonedObjectPool.removeAbandoned(AbandonedObjectPool.java:158) at org.apache.commons.dbcp.AbandonedObjectPool.borrowObject(AbandonedObjectPool.java:77) at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044) at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111) at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77) at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:625) at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:690) at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:717) at org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:767) at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.queryForObject(NamedParameterJdbcTemplate.java:211) at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.queryForObject(NamedParameterJdbcTemplate.java:219) at org.springframework.jdbc.core.namedparam.NamedParameterJdbcTemplate.queryForObject(NamedParameterJdbcTemplate.java:233)

这样这个服务的动态数据源功能就废了。可是这个服务还有其他功能用的是druid数据源，应该不受影响才对。再看看堆栈信息：

"http-nio-8210-exec-15" #79 daemon prio=5 os_prio=0 tid=0x00007fcba4002000 nid=0x7d9a waiting on condition [0x00007fcb6f6f6000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000000e1d2b0e0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at com.alibaba.druid.pool.DruidDataSource.takeLast(DruidDataSource.java:1891) at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1452) at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:1247) at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4619) at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:680) at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4615) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1225) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:1217) at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:90) at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:386) at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:87) at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:112) at org.hibernate.internal.SessionImpl.connection(SessionImpl.java:489) at sun.reflect.GeneratedMethodAccessor189.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:216) at org.springframework.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:201) at org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle.doGetConnection(HibernateJpaDialect.java:414) at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:177) at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:380) at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:377) at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:461) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:277) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:133) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:57) at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179) at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:213) at com.sun.proxy.$Proxy165.findOne(Unknown Source)

所有的druid的请求都卡在获取数据库连接这块DruidDataSource.takeLast，数据库连接不够用了？

按理说dbcp的连接用完了后，对另一块的DruidDataSource没影响啊。后来发现有蹊跷。

at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.mysql.jdbc.util.ReadAheadInputStream.fill(ReadAheadInputStream.java:101) at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:144) at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:174) - locked <0x00000000fe5427e8> (a com.mysql.jdbc.util.ReadAheadInputStream) at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3011) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3472) at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3462) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3903) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2530) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2683) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2486) - locked <0x00000000fe4dd4e8> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858) - locked <0x00000000fe4dd4e8> (a com.mysql.jdbc.JDBC4Connection) at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1966) - locked <0x00000000fe4dd4e8> (a com.mysql.jdbc.JDBC4Connection) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96) at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)

........

at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:99) at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:282) at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96) 

在执行dbcp的查询之前竟然开了事务！，检查代码发现，在获取dbcp连接执行查询的方法上加了@Transactional注解，这样执行这个方法之前会先打开druid的链接。也就是先用了的druid的连接不释放，然后又去执行dbcp的慢查询sql，相当于这一条sql同时卡住了两个连接资源。照成了整个服务无法响应！

解决方法，去掉动态数据源查询上面的@Transactional注解，同时保证dbcp连接使用期间没有对druid进行查询。

顺便说一下，dbcp坑很多，不能只是查询超时时间，dbcp2好一点，可以通过setDefaultQueryTimeout()方法设置查询超时。

建议还是用hikaricp,又快又好。

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 196,165评论 5赞 462
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 82,503评论 2赞 373
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 143,295评论 0赞 325
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 52,589评论 1赞 267
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 61,439评论 5赞 358
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 46,342评论 1赞 273
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 36,749评论 3赞 387
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 35,397评论 0赞 255
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 39,700评论 1赞 295
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,740评论 2赞 313
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,523评论 1赞 326
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 32,364评论 3赞 314
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 37,755评论 3赞 300
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,024评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,297评论 1赞 251
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 41,721评论 2赞 342
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 40,918评论 2赞 336