此系统所有用到数据库的地方都抛出此异常。于是祭出重启大法,重启过后,一切Okay。然后对应的系统人员开始排查这个问题,一直没有结果。
过了两天,又收到此类型的error日志报警,而且这一次是有两台系统同时爆出此种错误。紧急重启后,将此问题紧急报到我们这边处理。鉴于本人有丰富的IO处理经验,当然落到了本人头上。
在这个Bug里面很明显是Druid创建连接失败,原因如下:
如果说这两台是由于同机房问题出现统一的网络连接异常,那么并不能解释重启后正常这一现象。
可见,这边获取到的DruidConnectionHolder为null,则抛出异常。
Druid 获取连接的过程
在分析这个问题之前,先得看下Druid是如何创建连接的,下面是本人阅读Druid源码后画的示意图:
可见druid创建连接都是通过一个专门的线程来进行的,此图省略了大量的源码细节。
为何 Holde 为 null?
继续上源码
可见,如果触发条件,estimate<=0,则返回null。
上述源码的过程示意图如下:
继续追踪
由此可见,在获取连接的时候一直超时,不停的爆GetConnectionTimeoutException异常,明显是由于创建连接线程出了问题。那到底除了什么问题呢?由于Druid的代码比较多,很难定位问题点,于是还从日志入手。
大量 create connection error
当笔者和同事追查错误的源头的时候,在有大量的create connection error,奇怪的是,到了一个时间点之后,就只剩GetConnectionTimeoutException异常了。
继续分析,在出现create connection error的时候,还是有部分业务请求能够执行的。即获取到了连接。
翻了翻源码,create connection error是在创建连接线程打印的,如果这个异常没有继续打印,而同时连接也获取不到,就在很大程度上表明:
– 错误分界点
于是开始寻找什么时候create connection error开始销毁。于是通过笔者和同事在无数的错误日志中用肉眼发现了一个不寻常的日志隐蔽在大量的错误日志间:
在这个错误出现之后,就再也没有了create connection error,翻了翻另一台机器的日志,页是同样的现象!
– 源码寻找 Bug
隐隐就感觉这个日志是问题错误的关键,打出这个日志的源码为:
这边竟然在for(;;)这个死循环中break了!!!,那么这个线程也在break后跳出了死循环从而结束了,也就是说创建连接线程被销毁了!!!如下图所示:
为何 create holder error?
继续搜寻日志,发现create holder error之前,会有获取事务隔离级别的报错。那么结合源码,错误的发生如下图:
即在Druid的创建连接线程创建连接成功之后,还需要拿去数据库的holdability,isolation(隔离级别)等MetaData,在获取MetaData失败的时候,则会抛出异常,导致创建连接线程Break。
但是如果在handshake的时候就失败,那么由于Druid处理了这种异常,打印create connection error,并继续创建连接。
于是就有了在create holder error之前大量create connection error,在这之后没有了的现象。
完结了么?
Druid的Bug是弄清楚了,但是为何连接如此不稳定,有大量的创建连接异常,甚至于Druid前脚创建连接成功,后脚发送命令就失败呢?
由于每次内存泄露过小,同时Sharding Proxy设置的内存过大。所以上线后过了一个月才有频繁的GC现象。之前上线后,大家观察了一周,发现没有任何异常,就不再关注。与此类似,如果DB负载过高的话,笔者推测也会触发Druid的Bug。
终于这次的连环Bug算是填完了。