今天,正准备关机下班,突然斯盖普钉钉响了起来。纳尼?我一看,原来是我组里配(yi)合(kuai)工(mo)作(yu)的印度mm。
印度MM一上来就吐槽升级了vert.X组件,结果发布生产了以后炸了,出现了大量jdbc连接等待导致超时,看起来就像是资源池无法释放。
WARNING: Thread Thread[vert.x-worker-thread-18,5,main]=Thread[vert.x-worker-thread-18,5,main] has been blocked for 136191 ms, time limit is 60000 msio.vertx.core.VertxException: Thread blocked at java.lang.Object.wait(Native Method) at java.lang.Object.wait(Object.java:502) at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1104) at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106) at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
这时候,赶着要去做公交的我,只好安慰她, 我说,没事,you can find a better job.
但大概MM没听懂我是在开玩笑,想到疫情期间工作不好找,哭得更伤心了。
我一看这不行啊,再说"子公司的,又不能不帮",于是耐住性子看日志。
前情概要:这是一个连接数仓的系统,并发量不大,但是由于数仓架构比较老,经常会有长query。
MM这次只升级了netty和vert.X,但为何引发了大量的jdbc connection 超时呢?
MM又说,他在服务器日志文件的开头部分,发现了一些比较奇怪的日志
WARNING: Thread Thread[vert.x-worker-thread-9,5,main]=Thread[vert.x-worker-thread-9,5,main] has been blocked for 82189 ms, time limit is 60000 ms
io.vertx.core.VertxException: Thread blocked
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 java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
at org.netezza.internal.NzSocket.isDataAvailable(NzSocket.java:285)
at org.netezza.sql.NzConnection.isDataAvailable(NzConnection.java:1025)
虽然仍然是超时,但是和之后大批量出现的超时日志是不一样的,后者是因为jdbc连接池用光了在等待,并且量非常大,而这个错误量相对而言比较少,而且是已经获得链接的情况下,读取过慢,出现了socket timeout,并且mm说,发生在服务启动后的较早的一段时间。
JDBC线程池全部线程被占用?为什么最开始那些出现socket timeout的长时连接没有得到释放呢?最最关键的是,我通过走查代码,发现netezza jdbc的超时时间其实设置成300S,而不是日志中显示的60S。也就是说,即便是长query引发的socket timeout,也不是由jdc那一层引发的,人家还在high呢。
<bean id="xxx" class="xxxxxxxxxxxxxxxxxxxxxx.datasource.base.Cluster">
<constructor-arg name="name" value="xxxxxxxxx" />
<constructor-arg name="type" value="xxxxxxxxx" />
<property name="queryTimeout" value="300" />
善于思考的我,很快就得出了假设:
MM更新的vert.X新版本,有一个线程最大limit时间,即日志里出现的60000ms,超过这个时间,会释放线程占用的socket等资源,但jdbc的超时时间为300s,所以他不知道socket被关掉啊,还在傻傻的等socket返回内容呢(这是我猜想的),于是一直等,一直block,直到其他的超过60s的长查询请求把jdbc connection全部占用完了,导致所有新的jdbc请求全部等池子释放链接,直到vert.X超时返回。
有了猜想,于是我就叫MM把vert.X的线程超时时间设置大大大大大大的,mm说,
after using -Dvertx.options.maxEventLoopExecuteTime=100000000000, thread block gone
于是,享受着鸡哥,额,不是,印度MM,崇拜的眼光(鸡哥已经是过去式了),我在想,看似不相关的问题,其实之间是有一条线的,好的,我吹不下去了,其实问题就很简单,但是由于我运用了一些叙事技巧,导致你们觉得很有趣对吧。觉得有趣请双击666,可以得到印度mm的亲笔签名。