logical readahead mysql_记一次线上宕机事件

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

用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: RUNNABLEat 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,又快又好。