现象
3月3号晚上22点30分左右oracle数据库发生宕机,之后过5分钟左右重启成功,在数据库重启之后,两个业务节点(一样的配置),一个自动重连成功,一个自动重连失败。
排查
分析日志
首先还是看了下日志,发现重连成功的节点业务一切正常,而重连失败的节点一大片抛出超时异常
文章图片
从日志中可以看出,是去hikaricp获取连接的时候超时了。而之前数据库宕机的时候重连成功的节点异常日志如下
文章图片
可以看到也是获取连接超时了,但是如果你细看会发现有个点不一样:有问题的节点日志中显示的是BaseHikariPool,而没问题的节点显示的是HikariPool。经过代码排查发现,项目中引入了两个不同版本的HikariCP,一个是项目本身引入的3.4.5版本,另一个是Quartz引入的2.3.13版本,而有问题的节点引入的就是2.3.13版本,那时候用的名称还是BaseHikaricPool。那么问题来了,为什么两个一模一样的配置启动的节点会引用了不一样的包呢?这和环境加载包的顺序有关,参考这篇文章。
查看源码
在日志里分析出使用了不同的版本HikariCP之后,接着就开始分析2.3.13和3.4.5版本到底在设计上有什么不同,是否2.3.13版本存在获取连接的缺陷。
2.3.13版本去连接池获取连接流程如下:
文章图片
3.4.5版本去连接池获取连接流程如下:
文章图片
3.4.5版本的流程和2.3.13版本基本一样,做了稍许修改:
- 去除了AbstractQueuedLongSynchronizer的等待
- 添加了SynchronousQueue队列和等待者来获取连接
连接池满了并且所有连接状态都不为STATE_NOT_IN_USE。
看下归还连接逻辑
2.3.13:
文章图片
这里可以看出一个问题,如果state的CAS操作失败,状态会停留在STATE_IN_USE并且打印一个警告日志,如果池子里连接已满并且都是这种状态的连接,则后续的获取连接都会超时,也就是符合上面那种情况。
3.4.5:
文章图片
可以看到3.4.5版本会直接将state设置为STATE_NOT_IN_USE,这样后续从连接池中就能够获取到连接。
重现 接着开始重现一下这个问题,将本地代码hikaricp版本改为2.3.13,将本地数据库连接指向测试环境数据库并启动程序,在程序运行一会儿后关闭数据库。等待几分钟后再次启动数据库,发请求过去发现连接池会重新获取连接。问题暂时无法重新,说明应该是比较极端的多线程情况下才会出现,后面要再多线程试一下。
总结
目前从代码中看两个版本的设计,只能推断出可能是连接池满了并且所有连接状态做CAS操作为STATE_NOT_IN_USE失败导致,真正的原因还是无法确定。
平时系统中还是应该加好监控以及日志,在出问题的时候要及时把当时的jvm相关信息dump出来,事后去分析的话缺少很多信息是无法查到根本原因的,另外在开发的时候要注意版本冲突,不然会出现一个莫名其妙的问题。
参考资料
【HikariCP重连失败问题】https://zhuanlan.zhihu.com/p/...