mysql jdbc 超时_mysql超时异常的问题查询

###一、源起

同事在调试程序时遇到了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连接池在连接空闲时，总是重新获取连接，这个问题回头再议。