项目背景
一个Java语言写的任务系统,使用固定线程大小的线程池处理长时间任务,任务具体业务逻辑为周期性调用一个外部http接口。调用外部接口使用的是CloseableHttpClient
问题现象
某一天任务调用的外部http接口切换到新域名下,连续好几天发现线程池有偶现的任务线程不打印业务日志了(就像任务线程好像异常退出了一样),但是查询数据库,对应的任务状态并没有结束。线程池提交任务执行代码如下:
Future future = executorService.submit(() -> {
try {
//执行任务
} catch (InterruptedException e) {
//更新任务状态1
} catch (Exception e) {
//更新任务状态2
} finally {
//提交数据库
}
});
原因分析
1、如果是任务执行代码有异常,应该会走到finally更新数据库任务记录状态。数据库任务记录没有更新,说明线程任务还在执行(确定finally中的提交数据库代码没有异常)。
2、既然线程还在执行,对应任务却没有输出业务日志,就需要思考是不是线程阻塞了。
3、通过jstack -l ${pid} 查询jvm线程信息,并没有发现有线程存在共用对象互锁的情况。根据任务代码定位到某个异常任务对应的线程,发现状态是RUNNABLE,但是堆栈调用显示在这个方法上
"pool-2-thread-209" #476 prio=5 os_prio=0 cpu=5035.61ms elapsed=356247.91s tid=0x00007fcb90031000 nid=0x129c runnable [0x00007fcb199de000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(java.base@11.0.2/Native Method)
at java.net.SocketInputStream.socketRead(java.base@11.0.2/SocketInputStream.java:115)
at java.net.SocketInputStream.read(java.base@11.0.2/SocketInputStream.java:168)
at java.net.SocketInputStream.read(java.base@11.0.2/SocketInputStream.java:140)
at sun.security.ssl.SSLSocketInputRecord.read(java.base@11.0.2/SSLSocketInputRecord.java:448)
at sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(java.base@11.0.2/SSLSocketInputRecord.java:237)
at sun.security.ssl.SSLSocketInputRecord.decode(java.base@11.0.2/SSLSocketInputRecord.java:190)
at sun.security.ssl.SSLTransport.decode(java.base@11.0.2/SSLTransport.java:108)
at sun.security.ssl.SSLSocketImpl.decode(java.base@11.0.2/SSLSocketImpl.java:1152)
at sun.security.ssl.SSLSocketImpl.readHandshakeRecord(java.base@11.0.2/SSLSocketImpl.java:1063)
at sun.security.ssl.SSLSocketImpl.startHandshake(java.base@11.0.2/SSLSocketImpl.java:402)
- locked <0x000000070a6b62d8> (a sun.security.ssl.TransportContext)
at org.apache.http.conn.ssl.SSLConnectionSocketFactory.createLayeredSocket(SSLConnectionSocketFactory.java:436)
at org.apache.http.conn.ssl.SSLConnectionSocketFactory.connectSocket(SSLConnectionSocketFactory.java:384)
at org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect(DefaultHttpClientConnectionOperator.java:142)
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.connect(PoolingHttpClientConnectionManager.java:376)
at org.apache.http.impl.execchain.MainClientExec.establishRoute(MainClientExec.java:393)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:236)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
推测这个方法at java.net.SocketInputStream.socketRead0(java.base@11.0.2/Native Method) 一致阻塞?
4、查询*,发现有网友提到openjdk 8的版本,概率性存在socketRead0一直阻塞的情况,但是后续版本修复了这个问题。当前线上环境用的是openjdk 11,所以排除这个可能。
5、那为什么socketRead0会一直阻塞呢,是不是没有设置超时时间?阅读JDK文档,发现如果没设置socket超时时间(默认为0),socketRead0会一直阻塞,直到读到数据。
6、当前项目工程调用第三方http接口,使用的CloseableHttpClient发现没有设置超时时间
setSocketTimeout、setConnectTimeout,而这个时间会在底层socket连接和读socket缓冲区内容时会用到,默认为0,表示一直阻塞直到读取到内容。
先这样处理,紧急上线,看看后续效果