监控应用获取连接超时问题
引言
上周一去公司,被领导叫过去询问,业务监控平台 "批处理"任务, 是不是更改执行时间了，从原先的每小时整点执行变为现在的每小时16&45min 执行。
第一反应很懵,45min执行是此前做"测试"(稍后分析这个"测试")时 更改的，但每小时 16min执行，确实没有改过,难道是其他同事改过?(业务监控已经交接给其他同事了),
但应该不可能.虽然领导说是问问,不用改,但还是一连忐忑了几天. 趁着 T+1 联调,事情不太多，回头重新查看这个问题.
问题背景:
从备份库切换回生产库(100节点),然后问题就来了...
问题描述:
1.每次整点执行时,比如早上9:00,线程都会hang住一段时间,然后在9:15:46,前台调度页面显示执行完成,后台却在9:15:00 抛出"连接超时"异常。
因为当时在做迁移,没有更多时间来分析,所以将 执行时间从整点执行 更新 到 每小时45min,后续的效果来看,并未出现预料之外的情况.
原因分析:
如下为简化后的大致流程图:
image.png
将从几个方面来分析:
调度器、Druid数据源、JDBC超时、Oracle服务端等几个方面来分析。
其实解决这个问题最简单，直接有效的方法 ,根据现有的问题特征(这个问题在备份库是不存在的)
从生产库(100节点) 查询 :
- oracle 后台 net 日志
- oracle 服务端对jdbc 连接超时的配置
- 操作系统底层对socket超时的配置
- 防火墙
通过如上四个方面,基本可以确定问题产生的原因,不过 因为是生产库,也许 通常是没有权限去这么做的吧,那只能通过其他途径去查询原因了.
一:调度器
调度器的原因,是可以排除的，前台调度页面,显示执行开始时间 是在 09:45,而 后台记录显示，线程在被hang住15分钟后,抛出异常，重新获取连接后,将整个流程执行完毕！
15分钟,是不是很巧呢？
二:Druid数据源
问题特征:
1.线程在指定的时间启动,在hang住15分钟后，抛出"connection time out";
2.监控平台 与 "100节点"并不在一个网段中,对于内网,考虑会有防火墙的存在。
3.Druid连接池,对于连接的超时时间设置在60sec(100节点对连接的超时控制无法知晓,不过可以反推出来);
问题分析:
2.1 线程 在 被hang住的这段时间里，到底在做什么？
用jstat查看jvm内存使用情况,发现各区内存占用率较低，查看GC信息也没有异常。
再接茬查看线程栈，发现线程 hang 在socket底层的TCP套接字读取上:如图:
微信图片_20190714220852.jpg
-
当请求与服务器建立连接时，线程执行Socket的带参数的构造方法，或执行Socket的connect()方法时，会进入阻塞状态，直到连接成功，此线程才从Socket的构造方法或connect()方法返回。
-
当监控平台向服务器提交数据(query命令),线程从Socket的输入流读取服务器的响应数据;如果没有足够的数据，就会一直处于阻塞状态，以等待数据的到来,处于hang住的状态,Thread.interrupt()也无法结束掉这个线程.
-
直到读到了足够的数据，或者到达输入流的末尾，或者出现了异常，才从输入流的read()方法返回或异常中断。
通过跟踪 druid 代码,当前线程正在执行 query-"select 1 from dual",这是一条验证sql,本身不会有太大的数据量，但 线程一直 hang 住,等待服务端的响应(等待服务端写入数据,服务端写入数据完成会发送结束标志), 最可能的一种情况,服务端将该连接关闭,导致客户端无响应，一直处于等待状态。
一段时间后(15min),抛出"connection time out" (在没找到准确原因之前,将执行时间提前15min,也就是每个小时45min执行);
二:原因分析：
业务线程一直处于runable状态,但是一直hang住却没有返回值, 而方法链调用的源头是 Druid连接池的isValidConnection()方法。 问题似乎与 Druid的配置有关.
Druid在获取连接后,在验证连接的有效性时,被hang住,难道是连接超时了 ?
根据线程 是在调用 socketread 与服务端通信时 hang 住,且 调用源头来自 druid的 isValidConnection发起。
可以推断，是否连接因为超时,被服务端关闭，导致客户端发起socketread无响应,长时间 hang住 呢 ?
当前 druid 中配置的连接有效时长为60 sec ;
2.2 DruidAbstractDataSource源码分析:
public boolean isValidConnection(Connection conn, String query, int validationQueryTimeout) throws Exception {
if (query == null || query.length() == 0) {
return true;
}
Statement stmt = null;
ResultSet rs = null;
try {
stmt = conn.createStatement();
if (validationQueryTimeout > 0) {
stmt.setQueryTimeout(validationQueryTimeout);
}
rs = stmt.executeQuery(query);
return true;
} finally {
JdbcUtils.close(rs);
JdbcUtils.close(stmt);
}
}
查看调用链，在执行如上代码时 hang 住 , isValidConnection 的调用参数中，包含一个validationQueryTimeout,是否因为没有设置validationQueryTimeout或者设置的时间过长导致的呢？
1》在访问核心100节点的数据源中，配置validationQueryTimeout时长为:15s ,即 客户端等待服务端响应,超过15sec 服务端无响应后抛出异常，中断 被 hang 住的状态。
然而并没有效果~(自己都笑了);
Druid连接池里的连接(100节点)是超时的,那为什么没有被kill掉，配置的有效时长60sec.
Druid执行空闲连接的校验源码：
public class DestroyTask implements Runnable {
@Override
public void run() {
shrink(true, keepAlive);
//空闲连接的处理
if (isRemoveAbandoned()) {
removeAbandoned();
}
}
}
此处代码太长，是druid高效的核心，截取一段：
final int checkCount = poolingCount - minIdle;
final long currentTimeMillis = System.currentTimeMillis();
for (int i = 0; i < poolingCount; ++i) {
DruidConnectionHolder connection = connections[i];
if (checkTime) {
if (phyTimeoutMillis > 0) {
long phyConnectTimeMillis = currentTimeMillis - connection.connectTimeMillis;
if (phyConnectTimeMillis > phyTimeoutMillis) {
evictConnections[evictCount++] = connection;
continue;
}
}
long idleMillis = currentTimeMillis - connection.lastActiveTimeMillis;
if (idleMillis < minEvictableIdleTimeMillis) {
break;
}
if (checkTime && i < checkCount) {
evictConnections[evictCount++] = connection;
} else if (idleMillis > maxEvictableIdleTimeMillis) {
evictConnections[evictCount++] = connection;
} else if (keepAlive) {
keepAliveConnections[keepAliveCount++] = connection;
}
} else {
if (i < checkCount) {
evictConnections[evictCount++] = connection;
} else {
break;
}
}
}
int removeCount = evictCount + keepAliveCount;
if (removeCount > 0) {
System.arraycopy(connections, removeCount, connections, 0, poolingCount - removeCount);
Arrays.fill(connections, poolingCount - removeCount, poolingCount, null);
poolingCount -= removeCount;
}
keepAliveCheckCount += keepAliveCount;
} finally {
lock.unlock();
}
此处需注意的是：
- 与其他连接池逻辑不同，druid将超时的连接，所有连接，全部抛弃,并不依赖最小连接数的限制,将复杂问题简化。
- Druid判断连接是否超时的依据，来源 min 和 max. min当前监控平台设置的是60s,max为drudi默认的值,为7个小时，为什么默认是7个小时，为什么不是6个小时或者8个小时，这里不是巧合，后续再讨论这个"7个小时".
至少到这里，连接超时的原因找到了，引出了另一个问题: 为什么配置 statement的validationQueryTimeout超时，没有达到 超时中断线程的作用 ？
三:JDBC 超时
SUN公司一共定义了4中类型的JDBC，常用的是第四种，该类型的Driver完全由Java代码实现，通过使用socket与数据库进行通信
image.png
通过socket对字节流进行处理，当在网络操作中遇到问题的时候，将会消耗大量的cpu资源，并且失去响应超时。
应用与数据库间的timeout层级
image.png
即：简化后，应用 与 数据库的 timeout层级。
高级别的 timeout 依赖于低级别的 timeout ,只有当低级别的 timeout无误时,高级别的 timeout才能确保在正常。
例如：当 socket timeout 出现问题时, 高级别的 statement timeout 和 transcation timeout都将失效。
- 即使 设置了 statement timeout 时，当网络出错时,应用 也 无法从错误中恢复。
- statement timeout 无法处理网络连接失败的超时，它能做的仅仅是限制 statement 的操作时间。
- 网络连接失败时的 timeout 必须交由JDBC Socket 来处理,Socket控制着节点之间网络通信。
Druid是数据库连接的创建和管理，并不干涉timeout的处理。
当连接在Druid中创建，或是Druid发送校验query检查连接有效性的时候，socket timeout将会影响这些过程，但并不直接对应用造成影响。
当在应用中调用Druid的getConnection()方法时，可以设置获取数据库连接的超时时间，但是这和JDBC的timeout毫不相关。
3.1 JDBC的statement timeout处理过程
设置的是一个statement的执行超时时间，即driver等待statement执行完成，接收到数据的超时时间
注意:
statement的timeout不是整个查询的timeout，只是statement执行完成并拉取fetchSize数据返回的超时;
resultSet的next在必要的时候还会触发fetch数据，每次fetch的超时时间是单独算的，默认也是以statement设置的timeout为准
3.1.1 Oracle JDBC Statement的QueryTimeout处理过程
- 通过调用Connection的createStatement()方法创建statement
- 调用Statement的executeQuery()方法
- statement通过自身connection将query发送给Oracle数据库
- statement在OracleTimeoutPollingThread（每个classloader一个）上进行注册
- 达到超时时间
- OracleTimeoutPollingThread调用OracleStatement的cancel()方法
- 通过connection向正在执行的query发送cancel消息
3.2 JDBC的 socket Timeout ?
1.JDBC使用socket与数据库连接，数据库并不对应用与数据库间的连接超时进行处理。
2.JDBC的 socket timeout 在数据库被突然停掉或是发生网络错误（由于设备故障等原因）时十分重要。
3.由于TCP/IP的结构原因，socket没有办法探测到网络错误，因此应用也无法主动发现数据库连接断开。
4.如果没有设置socket timeout的话，应用在数据库返回结果前会无期限地等下去，这种连接被称为dead connection。
设置的是jdbc I/O socket read and write operations的超时时间，防止因网络问题或数据库问题，导致driver一直阻塞等待。(建议比statement timeout的时间长)
为了避免 dead connections，socket 必须要有超时配置。
socket timeout可以通过JDBC设置，socket timeout 能够避免应用在发生网络错误时产生无休止等待的情况，缩短服务失效的时间。
使用原则:
- socket timeout 的超时时长 必须 大于 statement timeout；
- 不推荐使用socket timeout来限制statement的执行时长，因此socket timeout的值必须要高于 statement timeout，否则，socket timeout将会先生效，这样statement timeout就变得毫无意义，也无法生效。
四:结论
目前，分析了 监控平台连接池中的连接(100节点)为什么超时 以及 为什么设置 statement超时没有任何效果。
4.1 为什么会在每小时45min执行：
因为连接超时，服务端关闭连接，导致客户端socketRead读取时，服务端无响应，长时间 hang 住。时长15min.所以，当时在没有查清原因之前,为了 在 准点执行,在当时测试此问题时,将执行时间提前15min.
4.2 为什么会在每小时16min执行？
- 造成这个异常时间点执行"批处理"监控任务，虽然看似诡异，还是可以还原执行原理：在执行"批处理"时，若 连接池中包含N个连接，则延迟的时间在N*15;
- 假设09:45开始执行"批处理"监控任务，此时,因为平台在09:00时执行过其他任务(访问100节点),连接池中剩余2个idle connection,其 idle time = 45min,访问100节点时,将会因连接超时，导致服务端Close.才产生文章开头的"hang住15min"后抛出timeout 异常。
- 由此可推断，100节点对连接的超时时间，不超过45min.
- 2个 idle 连接将耗费30min,实际开始执行的时间是在10:15:??(9:45+30min) 开始，重新创建连接，查询数据，返回，并在10:16:?? 返回异常告警提示。
4.3 为什么 每次 hang 住的时间都是15min?
- 因为没有具体的数据，不确定15min是因为防火墙对TCP/IP的超时时间 或者是 OS Socket time out 导致。
- 很多时候, OS time out对socket的配置起决定性作用。
- OS time out 默认为15min(区分版本),是不是这么巧呢，不要逗我啦~(内部防火墙对TCP/IP的阻断)
4.5 如何解决？
- 根据目前监控平台的异常特征，以及查阅Druid源码分析，可以初步推断："100节点"的连接的有效时间，大概是30min左右。
- 假设"100节点"对超时控制在30min，并不意味着query命令可以达到30min,这取决于socket timeout 和 statement timeout 以及 内部防火墙的超时配置,复杂一点的可能还涉及到OS层。因为没有确切的数据，就不展开分析了。
45&16min问题的解决方案：
在Druid数据源中，指定max的具体时长即可，这需要根据"100节点"的数据来配置.
以上所有问题的产生，只发生在"100节点".
结尾：
其实,分析到这里，什么结论也没有 ，是不是 没有意义呢 ?
- 记录这段过程，不在于 有具体的结论，更多于一种解决问题的思路,对于生产问题的分析,很多时候,解决思路 更重要，尤其是在极端复杂的业务场景中。
- 其实在再保的几年中,感受最大的是 解决问题的思路,比 实际解决问题 更重要,当不确定问题来源于具体哪一个流程，可以先确定哪一个流程一定是没有问题的.
- 在此前遇到的各种生产问题, 业务场景极其复杂,模块结构交织,数据量庞大,绝大部分问题都要涉及到多个接口交互,多个流程(系统趋于中心化),多套数据表 等.
- 比如"金额相差1分钱"，无法确定是结算,帐单,复核,还是分保哪个流程的问题，更有可能是复核，帐单，结算不在一天，兑换率的差异导致相差一分钱等。
只是对解决问题的思路 以及 工作中的一段总结~
