问题描述
公司一个新项目上线,处于试运行阶段,这个项目虽然是外网可访问的,故部署在了 DMZ 区,但试运行阶段只给了公司内少部分员工地址和账号(其中包括一些领导),故访问量很小,但项目还是挺重要的。
试运行阶段中,项目应用日志中不定期会报异常,尤其是在刚上午刚开始使用时,还有空闲一段时间后再次使用时,具体异常如下:
ERROR [com.alibaba.druid.util.JdbcUtils] - close connection error
java.sql.SQLRecoverableException: IO Error: Broken pipe
at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:556)
at oracle.jdbc.driver.PhysicalConnection.close(PhysicalConnection.java:3984)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:167)
at com.alibaba.druid.filter.stat.StatFilter.connection_close(StatFilter.java:254)
at com.alibaba.druid.filter.FilterChainImpl.connection_close(FilterChainImpl.java:163)
at com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl.close(ConnectionProxyImpl.java:115)
at com.alibaba.druid.util.JdbcUtils.close(JdbcUtils.java:79)
at com.alibaba.druid.pool.DruidDataSource.discardConnection(DruidDataSource.java:965)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:932)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4534)
at com.alibaba.druid.filter.stat.StatFilter.dataSource_getConnection(StatFilter.java:661)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4530)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:884)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:876)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:92)
at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:205)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:420)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:257)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:95)
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.aop.framework.CglibAopProxy D y n a m i c A d v i s e d I n t e r c e p t o r . i n t e r c e p t ( C g l i b A o p P r o x y . j a v a : 644 ) a t x x x . x x . m o d u l e s . d e p o s i t . a p i . s e r v i c e . D e p o s i t A p i S e r v i c e DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:644) at xxx.xx.modules.deposit.api.service.DepositApiService DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:644)atxxx.xx.modules.deposit.api.service.DepositApiService E n h a n c e r B y S p r i n g C G L I B EnhancerBySpringCGLIB EnhancerBySpringCGLIB$59c8f6e2.doRecharge()
at xxx.xx.modules.deposit.FundDepositController.rechargeConfirm(FundDepositController.java:125)
…Caused by: java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)
at java.net.SocketOutputStream.write(SocketOutputStream.java:159)
at oracle.net.ns.DataPacket.send(DataPacket.java:210)
at oracle.net.ns.NetOutputStream.flush(NetOutputStream.java:230)
at oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:312)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:260)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:185)
at oracle.net.ns.NetInputStream.read(NetInputStream.java:102)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)
at oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)
at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:290)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:192)
at oracle.jdbc.driver.T4C7Ocommoncall.doOLOGOFF(T4C7Ocommoncall.java:61)
at oracle.jdbc.driver.T4CConnection.logoff(T4CConnection.java:543)
… 69 more
从异常信息可以看出,问题是发生在 Druid 数据库连接池在关闭物理数据库连接时,报了 SocketException: Broken pipe,但为什么在使用时 Druid 会关闭数据库连接,关闭数据连接又为什么会报 SocketException 呢?这个异常到底对系统有多大的影响呢?下面一步步分析。
问题逐步分析
1、java.net.SocketException: Broken pipe 异常是怎么产生的?有什么影响?#
项目中使用是的 Druid 连接数据库,可为什么在系统空闲一段时间后再使用,会尝试关闭数据库连接,而且关闭的时候还抛了 java.net.SocketException: Broken pipe 呢?
从异常堆栈信息,或者翻看 Druid 源码可以知道,异常是发生在从数据库连接池中获取连接,用于后续数据库操作时,在执行到DruidDataSource.getConnectionDirect(maxWaitMillis)方法
时,有如下逻辑:
public DruidPooledConnection getConnectionDirect(long maxWaitMillis) throws SQLException {
//循环
for (;;) {
//maxWaitMillis时间内从连接池获取一个连接
DruidPooledConnection poolalbeConnection = getConnectionInternal(maxWaitMillis);
//testOnBorrow为true,即从池中获取连接后需要检查连接
if (isTestOnBorrow()) {
boolean validate = testConnectionInternal(poolalbeConnection.getConnection());
if (!validate) {
if (LOG.isDebugEnabled()) {
LOG.debug("skip not validate connection.");
}
Connection realConnection = poolalbeConnection.getConnection();
discardConnection(realConnection);
continue;
}
}
else {
Connection realConnection = poolalbeConnection.getConnection();
//如果连接已经关闭,再从池中获取一个
if (realConnection.isClosed()) {
discardConnection(null); // 传入null,避免重复关闭
continue;
}
//testWhileIdle为true,即空闲后需要检查连接
if (isTestWhileIdle()) {
//连接空闲时间(当前时间 - 上次ActiveTime)
long idleMillis = System.currentTimeMillis()
- poolalbeConnection.getConnectionHolder().getLastActiveTimeMillis();
//连接空闲时间 > timeBetweenEvictionRunsMillis,检查连接
if (idleMillis >= this.getTimeBetweenEvictionRunsMillis()) {
boolean validate = testConnectionInternal(poolalbeConnection.getConnection());
//连接检查失败,打印log,丢弃连接,再获取一个连接
if (!validate) {
if (LOG.isDebugEnabled()) {
LOG.debug("skip not validate connection.");
}
discardConnection(realConnection);
continue;
}
}
}
}
//如果开启了连接超时回收
if (isRemoveAbandoned()) {
StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
poolalbeConnection.setConnectStackTrace(stackTrace);
poolalbeConnection.setConnectedTimeNano(); //设置当前时间为ConnectedTime
poolalbeConnection.setTraceEnable(true);
synchronized (activeConnections) {
activeConnections.put(poolalbeConnection, PRESENT); //将连接放入activeConnections Map
}
}
if (!this.isDefaultAutoCommit()) {
poolalbeConnection.setAutoCommit(false);
}
return poolalbeConnection;
}
}
简单来说,在从 Druid 获取数据库连接时,可以进行 test,这段代码中包含testOnBorrow
(借出时检查)和testWhileIdle
(空闲时检查)的逻辑,此项目在配置文件中
testOnBorrow = false
testWhileIdle = true
timeBetweenEvictionRunsMillis = 60000(60s)
故只会在连接空闲 60s 后再次使用时进行检测,其实就是执行一个 SQL,而在执行 SQL 时如果失败了,就会调用JdbcUtils.close(realConnection)
关闭连接,在关闭这个连接时抛了 SocketException 异常,但其实这个异常倒不会对希望获取 Connection 执行 SQL 查询的程序造成太大影响,因为 JdbcUtils.close() 方法中捕获了这个异常,打印 log,并没有上抛
public static void close(Connection x) {
if (x == null) {
return;
}
try {
x.close();
} catch (Exception e) {
LOG.debug("close connection error", e);
}
}
那么 java.net.SocketException: Broken pipe 是什么意思呢?
其实就是与数据库建立的 tcp 连接因为某些原因断开了,而导致了 “管道破裂”。一般数据库连接池会与数据库保持长连接,在需要的时候省去建立连接的过程,直接使用,而为什么这些空闲的连接会被断开呢?被谁断开了?
2、为什么数据库 TCP 连接会被断开?#
一开始百思不得其解,想着是因为 Oracle 数据库主动断开了连接吗?因为某些原因,比如从服务器到数据库的连接太多?明显不是,这个项目还在试运行阶段,用的人不多,且观察 Druid 的连接池监控,一般建立的连接也就几个
后来和同事讨论的过程中得知别的项目组也发生过类似的情况,而他们和这个项目的共同之处就在于服务都是在 DMZ 区,外网可访问,而数据库在内网,需要通过防火墙才能访问到数据库。于是去找负责维护网络、防火墙的同事了解,原来防火墙有一个 TCP 超时时间,目前设置的为半小时,其意义是,对于通过防火墙的所有 TCP 连接,如果在半小时内没有任何活动,就会被防火墙拆除,这样就会导致连接中断。在拆除连接时,也不会向连接的两端发送任何数据来通知连接已经拆除。
这下数据库连接断开的原因找到了,那么这就是一个应用与数据库在不同的网络中,连接需要经过防火墙的场景中会遇到的一个典型问题,怎么能够使应用和数据库之间即使比较空闲也能够保持一定数量的长连接,是亟待解决的。
3、防火墙切断数据库连接会造成的影响#
数据库会话正在执行耗时长的 SQL
切断连接之前,连接对应的 Oracle 会话正在执行一个耗时特别长的 SQL,比如存储过程而在此过程中没有任何数据输出到客户端,这样当 SQL 执行完成之后,向客户端返回结果时,如果 TCP 连接已经被防火墙中断,这时候显然会出现错误,连接中断,那么会话也就会中断。但是客户端还不知道,会一直处于等待服务器返回结果的状态。
如果客户端没有针对这种执行耗时长的 SQL 的连接回收机制,那么客户端这个连接将一直处于等待状态,如果客户端不断执行这种耗时长 SQL,那么客户端堆积的等待连接将越来越多。
Druid 连接池的removeAbandoned
相关配置以及逻辑,就是为了解决这种连接回收设置的。
数据库会话空闲
切断连接之前,Oracle 会话一直处于空闲状态,在防火墙中断之后,客户端向 Oracle 服务器提交 SQL 时,由于 TCP 连接已经中断,这时客户端侦测到连接中断,那么客户端就会报 ORA-03113/ORA-03114 这类错误,然后会话中断。但是在 Oracle 服务器端,会话一直在处于等待客户端消息的状态。
而对于 Druid 这种有 testOnBorrow、testWhileIdle 的检测机制,且检测失败可以重新建立连接的连接池,空闲的被防火墙切断的连接在后续会被不断重建,而在数据库服务器端,则连接越来越多,即会话数越来越多,甚至最终超过了数据为最大连接数。
解决方法
1、调大防火墙的连接切断时长#
这是一个临时解决方法,比如将防火墙的连接超时时间调整为 8 小时,这样可以尽量避免空闲连接的切断,但无法完全避免,因为无法预计连接会被空闲多久,如果你的系统不是总有人访问的话,那么连接迟早会因为空闲而被切断,导致一些不可预计的问题,而调大超时时间只是缓解而已
2、tcp keepalive 功能#
tcp 的 keepalive,其实就是用来保持 tcp 连接的,其原理简单说就是如果一个 TCP 连接在指定的时间内没有任何活动,会发送一个探测包到连接的对端,检测连接的对端是否仍然存在,如果对端一定时间内仍没有对探测的响应,会再次发送探测包,发送几次后,仍然没有响应,就认为连接已经失效,关闭本地连接。
tcp keepalive 并不是默认开启的,在开发程序时可以设置 tcp keepalive 为 true,这样 tcp 连接在一定时间内没有任何数据报文传输则启动探测,这个时间一般是操作系统规定,Linux 系统中可以通过设置net.ipv4.tcp_keepalive_time
来修改,默认是 7200 秒,即 2 小时。当然在编程时也可以设置这个时间用于当前 socket,但是 Java 的 Socket API 中好像只有设置 keepalive=true,并没法设置 tcp_keepalive_time
当设置了 tcp keepalive 之后,只要 tcp 探测包发送的时间小于防火墙的连接超时时间,防火墙就会检查到连接中仍然有数据传输,就不会断开这个连接。
使用 JDBC 创建的数据库 tcp 连接是没有设置 keepalive 的,这点可以通过 Linux 的 netstat 或 ss 命令在数据库客户端(即应用端)验证
使用命令 netstat -ano 或 ss -ano,其中参数 o 都是显示 timer 计时器,timer 计时器在连接建立状态下可以对连接保活计时
netstat 命令对没有开启 keepalive 的 tcp 连接显示为:off (0.00/0/0)
ss 命令对没有 keepalive 的 tcp 连接,不会显示 timer 计时器
3、Oracle 数据库的 DCD#
Oracle 提供了类似 tcp keepalive 的机制,也就是 DCD(Dead Conneciton Detection)。在 $ORACLE_HOME/network/admin/sqlnet.ora 文件中增加如下一行:
sqlnet.expire_time=NNN
这里 NNN 为分钟数,Oracle 数据库会在会话 IDLE 时间超过这个指定的时间时,检测这个会话的对端(即客户端)是否还有效。避免客户端由于异常退出,导致会话一直存在。
同样的如果 DCD 的时间比防火墙切断空闲连接的时间短,连接也可以一直保持
4、程序不定时执行查询#
以上几种方法要么是利用 tcp 连接 keepalive 特性,要么是采用数据库端的空闲连接检测,我们的程序中也可以主动做这种心跳检测
Druid 数据库连接池从 1.0.28 开始,添加了 druid.keepAlive 属性,默认关闭
打开 druid.keepAlive 之后,当连接池空闲时,池中的 minIdle 数量以内的连接,空闲时间超过 minEvictableIdleTimeMillis,则会执行 keepAlive 操作,即执行 druid.validationQuery 指定的查询 SQL,一般为 select * from dual,只要 minEvictableIdleTimeMillis 设置的小于防火墙切断连接时间,就可以保证当连接空闲时自动做保活检测,不会被防火墙切断