记录线上一次线程hang住问题

时间:2021-05-28 07:58:45

线上发现执行某特定任务在某个特定时间点后不再work。该任务由线程池中线程执行定时周期性调度,根据日志查看无任何异常。从代码研判应该无关定时任务框架,因为对提交的定时任务做了wrap,会将异常都catch住,保证下次仍然能够正常调度。

通过jstack导出堆栈信息,发现问题线程的堆栈信息如下:

"OperatorDispatch" #338 prio=5 os_prio=0 tid=0x00007f1140d63000 nid=0x2edc runnable [0x00007f101f8cd000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
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 <0x00000006c4a6d190> (a com.mysql.jdbc.util.ReadAheadInputStream)
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3008)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3469)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3459)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3900)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2490)
- locked <0x00000006c501d648> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
- locked <0x00000006c501d648> (a com.mysql.jdbc.JDBC4Connection)
at com.mysql.jdbc.PreparedStatement.execute(PreparedStatement.java:1197)
省略

研判出线程hang在socketRead0方法中,仔细排查后发现socketRead0中的timeout为0,也即没有超时设定。

网上对于此问题有不少说法,有的是说读取大量数据时会出现,需要设置limit。也有人提交了相关的bug,如74379

我倒是觉得深入理解JDBC的超时设置这篇文章不错,也倾向于原因是网络抖动,但无论如何应用层的应该对socket连接设置超时参数。

最终在jdbc连接串中加上socketTimeout参数设定超时时间。

参考

深入理解JDBC的超时设置

聊聊jdbc socketTimeout的设置