码农大战宝莱坞

今天,正准备关机下班,突然斯盖普钉钉响了起来。纳尼?我一看,原来是我组里配(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的亲笔签名。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
平台声明:文章内容(如有图片或视频亦包括在内)由作者上传并发布,文章内容仅代表作者本人观点,简书系信息发布平台,仅提供信息存储服务。

推荐阅读更多精彩内容