###一、源起
同事在调试程序时遇到了Mysql异常
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException:Communications link failure Last packet sent to the server was X ms ago
###二、分析
这是由于JDBC客户端的mysql连接在长时间不活动之后断开了,断开之后的首次请求会抛出这个异常。查询mysql超时设置:show variables like ‘%timeout%’,查看和连接时间有关的MySQL系统变量,得到如下结果:
他的一个查询程序跑了148秒,在同一个事务里再执行update操作时,程序抛出了上面的异常。
一开始我以为是在这个查询执行时间过长,mysql主动切断了连接。但是很奇怪的是在navicat单独执行这个sql,五六秒就能得到结果,虽然也很慢,但是没那么离谱。
这时候我怀疑,是不是结果在程序中早就查出来了,但是由于程序本身的原因,导致总的执行时间超过了wait_timeout设置的值,导致mysql server端切断了不活动的连接。
在验证这个问题时,由于同事的maven依赖很多,导致依赖关系非常乱。日志用的是log4j2,但是mvn dependency:tree查看到了很多log4j-1.2、slf4j各种桥接的依赖,很多都是由于依赖dubbo暴露接口打成的jar包,而形成的间接依赖。在做了一些列exclusion后,终于能看到全面的日志。之后就发现了log4jdbc打印的很多的ResultSet日志:
这个sql查询到了9K+的结果,这个resultset日志打了大概2W行,可以看到是log4jdbc配置问题导致程序在获取ResultSet后浪费了大量的时间进行结果分析和日志记录,导致mysql连接超时。
###三、解决
由于项目本身用的是druid和Mybatis,都具有日志打印的功能,对于log4jdbc的需求其实很小,就把log4jdbc去掉了。问题解决。
###四、总结
如果不对表象进行分析,很难真正的解决问题。日志对于程序调试还是尤其重要的。另外wait_timeout的值过小,是否会引起druid连接池在连接空闲时,总是重新获取连接,这个问题回头再议。