JDBC链接出现超时问题
今日线上突发一个问题,应用假死,不接受http请求,排查日志,发现有大量的 The last packet successfully received from 异常。
首先排查数据库和链接池配置
<bean id="dataSource" class="org.apache.tomcat.jdbc.pool.DataSource"
destroy-method="close">
<!-- Connection Info -->
<property name="driverClassName" value="${jdbc.driver}"/>
<property name="url" value="${jdbc.url}"/>
<property name="username" value="${jdbc.username}"/>
<property name="password" value="${jdbc.password}"/>
<!-- Connection Pooling Info -->
<property name="maxActive" value="${jdbc.pool.maxActive}"/>
<property name="maxIdle" value="${jdbc.pool.maxIdle}"/>
<property name="defaultAutoCommit" value="true"/>
<property name="validationQuery" value="${jdbc.validationQuery}"/>
<property name="testOnBorrow" value="true"/>
<!-- 连接Idle一个小时后超时 -->
<property name="timeBetweenEvictionRunsMillis" value="3600000"/>
<property name="minEvictableIdleTimeMillis" value="3600000"/>
</bean>
对比mysql 配置 的timeout配置
链接池的超时时间远远小于 数据库的wait_timeout ,配置没有问题
wait_timeout wait_timeout 服务器关闭非交互连接之前等待活动的秒数
数据库wait_timeout配置的3600s(1小时)、业务线程闲置状态下和数据库保持的连接存活1个小时后数据库主动断开连接,这个时候有新的数据库操作请求、拿到该连接去执行validationQuery检测连接是否有效,由于数据库已经主动断开连接、执行检测sql就会抛出上面的错误。问题的本质还是druid线程池里没有及时清除无效的数据库连接导致。
但数据库的判断认为的连接超时时间是 timeBetweenEvictionRunsMillis = 3600000 < wait_timeout = 31536000 故问题不在此
排查应用程序
使用arthas监控线程,果不其然,出现了10running的http-nio线程,打开一个查看一下,果然有线程死锁
[arthas@23223]$ thread 167
"http-nio-30030-exec-113" Id=167 RUNNABLE (in native)
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:112)
at com.mysql.jdbc.util.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:159)
at com.mysql.jdbc.util.ReadAheadInputStream.read(ReadAheadInputStream.java:187)
- locked com.mysql.jdbc.util.ReadAheadInputStream@5c14cebc
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3140)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3597)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3586)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4131)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2597)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2758)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2820)
- locked com.mysql.jdbc.JDBC4Connection@eba881e
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2769)
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:907)
- locked com.mysql.jdbc.JDBC4Connection@eba881e
at com.mysql.jdbc.StatementImpl.execute(StatementImpl.java:791)
at net.sf.log4jdbc.StatementSpy.execute(StatementSpy.java:842)
at org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:455)
at org.apache.tomcat.jdbc.pool.PooledConnection.validate(PooledConnection.java:395)
at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:777)
at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:618)
at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:188)
at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:128)
at org.springside.modules.persistence.Hibernates.getJdbcUrlFromDataSource(Hibernates.java:47)
at org.springside.modules.persistence.Hibernates.getDialect(Hibernates.java:30)
at cn.infisa.obstetrics.respository.DaoUtils.getDatabaseDialect(DaoUtils.java:130)
at cn.infisa.obstetrics.respository.DaoUtils.getUrl(DaoUtils.java:151)
at cn.infisa.obstetrics.respository.DaoUtils.getDataList(DaoUtils.java:174)
at cn.infisa.obstetrics.respository.hospital.PatientInfoJdbcDao.getTimeline(PatientInfoJdbcDao.java:136)
at cn.infisa.obstetrics.service.hospital.PatientInfoService.getTimeline(PatientInfoService.java:74)
at cn.infisa.obstetrics.service.hospital.PatientInfoMenuService.assemPatientTimeline(PatientInfoMenuService.java:375)
at cn.infisa.obstetrics.web.record.PatientInfoController.getTimeline(PatientInfoController.java:134)
at sun.reflect.GeneratedMethodAccessor149.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
线程调用过程中,有三把锁,分别位于:
- com.mysql.jdbc.StatementImpl.execute synchronized (locallyScopedConn.getConnectionMutex()) Line:797
- com.mysql.jdbc.ConnectionImpl.execSQL synchronized (getConnectionMutex()) Line:2779
- com.mysql.jdbc.util.ReadAheadInputStream public synchronized int read(byte b[], int off, int len) throws IOException Line 176
最后锁住在 socketRead0 方法,而socketRead0 是一个native方法,有一个参数表示方法的超时设置-timeout
private int socketRead(FileDescriptor fd,
byte b[], int off, int len,
int timeout)
throws IOException {
return socketRead0(fd, b, off, len, timeout);
}
private native int socketRead0(FileDescriptor fd,
byte b[], int off, int len,
int timeout)
throws IOException;
什么是 Socket 超时
JDBC 驱动是用 Socket 方式与数据库连接的,应用程序和数据库之间的连接超时并不是由数据库处理的。
当数据库突然宕掉或发生网络错误(设备故障等)时,JDBC 驱动的 Socket 超时的值是必须的。由于 TCP/IP 的结构,Socket 没有办法检测到网络错误,因此应用不能检测到与数据库到连接断开了。如果没有设置 Socket 超时,应用程序会一直等待数据库返回结果。(这个连接也被叫做“死连接”) 为了避免死连接,Socket 必须要设置超时时间。Socket 超时可以通过 JDBC 驱动程序配置。通过设置 Socket 超时,可以防止出现网络错误时一直等待的情况并缩短故障时间。
原因分析
通过这儿明白了,socket链接超时,导致链接池中数据库占满,新线程申请不到链接,故http请求不响应;在socket超时后,释放链接,就会抛出大量的超时(The last packet successfully received from)错误。
解决办法
配置jdbc参数,在一个合理的范围内影响,超时即停止。
jdbc.url=jdbc:log4jdbc:mysql://ip:port/dbname?useUnicode=true&characterEncoding=utf-8&connectTimeout=60000&socketTimeout=60000
参考:
https://blog.csdn.net/jiadajing267/article/details/79516989
https://blog.csdn.net/java1993666/article/details/87889941
深入理解 JDBC 的超时