今天的问题困扰了我不知道多少个夜晚,为了解决这个问题我和团队花费了不少时间,但是最终看下来还是特别的值得!
最早的时候,问题的现象并不是: Connection is not available, request timed out after 5000ms.当时我们数据库连接池用的还是C3P0,我就发现有些业务sql执行的也很慢,sql 90%的都会在10ms内(不是慢sql),但是总会时不时的有一些执行要好几千毫秒。以上的现象都是通过pinpoint观察到的。
想了下觉得是可能是连接池不行,太老了,查了一下java 里用的比较多,比较流行连接池如c3p0、dbcp、druid 、hikaricp,也看到网上有对它们的比较, C3P0确实不行了,hikaricp是最好,刚好单位也在推hikaricp 于是我们换上了hikaricp。本以为问题应该得到了解决,然而并没有什么卵用。打开pinpint后发现还是老样子
execute()还是执行很长时,但是有一个不一样的点,用C3P0时pinpoint没有追踪到getConnection()方法,这次多了getConnection()方法,而且有时getConnection的时间会很长。最终是一个本来执行时间很短的方法,一会是execute时间比较长,一会又是getConnection时间比较长。
因为一开始这种现少,也没有对业务产生什么影响,后来就不再向下查了。但时随着时间推移,又生产了新的问题,日志开始报一些数据库的错误,那就是跟标题一样的 :
org.springframework.jdbc.CannotGetJdbcConnectionException: Could not get JDBC Connection; nested exception is java.sql.SQLTransientConnectionException: XXPool – Connection is not available, request timed out after 5000ms.
sql执行报错了,这。。。开始影响业务了。不能再忍了,接着查。打pinpoint看:
跟日志也对应的上,后来这个错误越来越多。我们看了一下连接池配置
得出想法结论:连接池里的连接不够用了,因为在等待连接所以超时了,并且也跟上面我说的getConnection()方法对的上,(还里还有一个无解的execute()耗时长)。
我们开始想办法验证我们的结论,接入hikaricp时我们通过
MBean (JMX) Monitoring
把hikaricp的一些连接池数据都存到了库里,Idle Connection,Active Connections,Total Connection ,Waitting Connection 通过数据观察我们发现没有Waitting,Idle也很多,不像是连接池打满的样子,那会不会是连接泄露,我们又加了连接池参数leakDetectionThreshold 来观察。发现并没有连接泄露,但是这次通过日志,我们又发现了新的错误:
connection is dead 这个问题的出现,又让我们做了一系列的思考!!!为什么会dead?
因为从连接池里取到的连接都是dead 所有会connnection()时间长,我们看了一下源代码,在取连接时,hikaripc会对连接做测试,于是我们又给连接池加配置,
参数一加不得了,新错误又来了:java.sql.SQLTimeoutException: ORA-01013: user requested cancel of current operation
ORA-01013 网上查了一通,解释多为锁表导致,问了我的老朋平安的oracle大牛,也在反问我是不是有锁表问题,销表会导致这上问题,但是这个问题确不一定都是锁表导致,事实证明真不是锁表,哈哈。当时找了dba确实也没有找到锁表.
不玩了,实在查不下去了,前前后后查了快两周了,版本上了几个,玩不下去了。上大佬!这次集齐了,dba,中间件,主机,网络,运维5个领域的大佬,召唤神龙。真的是人多力量大有了结论:应用到数据库存在很大的延时!
后面的故事就不扯了,就是换网卡,网线等。。。解决了延时问题,这次问题是真的得到了解决!
这里做个总结:软件是个复杂的东西,所应用到的技术更是广泛。 作为开发人员,思维和技术能力可能仅仅停留在了应用层,没有想到过,会向下(外)思考,会在网络层或者硬件上出现问题。这也对我们开发技术提出了高的要求。
另外,有问题(bug)真的没什么好怕的,解决了问题,bug带给你的知识和成长更是一笔未来价值。
最后,感谢我的团队和同事。未来我们还要一起努力!
努力吧,不用考虑结果
。也希望这篇文章对大家有帮助。