最近一个项目里面出现了一个比较诡异的问题:
页面上有个功能不定期的报错Communication error
碰到这种问题我们第一时间怀疑是网络问题,但是客户端工具可以正常连数据库,页面上其他功能也没报错
所以可以排除网络问题,为方便跟踪问题,我们可以开启DM JDBC的日志,获取更详细的信息
[ERROR - 2020-04-26 11:36:58] tid:262{ conn-33, pstmt-3706 } execute();
dm.jdbc.driver.DMException: Communication error
at dm.jdbc.driver.DBError.throwException(DBError.java:683)
at dm.jdbc.c.a.a(DBAccess.java:897)
at dm.jdbc.c.a.a(DBAccess.java:365)
at dm.jdbc.driver.DmdbPreparedStatement.executeInner(DmdbPreparedStatement.java:212)
at dm.jdbc.driver.DmdbPreparedStatement.do_execute(DmdbPreparedStatement.java:301)
at dm.jdbc.filter.FilterChain.PreparedStatement_execute(FilterChain.java:5498)
at dm.jdbc.filter.log.LogFilter.PreparedStatement_execute(LogFilter.java:8061)
at dm.jdbc.filter.FilterChain.PreparedStatement_execute(FilterChain.java:5494)
at dm.jdbc.driver.DmdbPreparedStatement.execute(DmdbPreparedStatement.java:1625)
通过语句句柄:pstmt-3706可以找到报错的SQL语句和它的参数
然后可以根据语句和参数自己写一个小程序进行验证,发现并不会报错,SQL单独在客户端中执行也不会报错,这就有点费解了
接下来我们查一查数据库的SQL日志,看看是什么情况
从SQL日志可以看出报错是-6007:连接异常,并且是在执行几秒钟之后,这个很大的可能性是SQL超时然后断开了连接
就有两个可能性:1.数据库端对用户设置了资源限制 2.应用对SQL设置了超时
经过排查,我们发现数据库并未对用户设置资源限制,仔细分析JDBC日志发现应用调用了JDBC的接口设置了连接限制
--JDBC日志中有很多类似的信息,说明应用针对不同SQL设置了不同的超时时间
setNetworkTimeout(ThreadPoolExecutor, Integer); [PARAMS]: java.util.concurrent.ThreadPoolExecutor@49e62b17[Running, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 111], 5000;
setNetworkTimeout(ThreadPoolExecutor, Integer); [PARAMS]: java.util.concurrent.ThreadPoolExecutor@49e62b17[Running, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 110], 15000;
可是询问客户的开发人员,他们说没有对SQL设置超时时间,只在连接池中做了配置,如下:
显然这个设置和我们分析到的现象不太一致,JDBC日志里面可以看了到应用多次调用接口设置了超时时间,
并且每次时间不太一致,应该另有原因,这时我们可以百度一下,JDBC中还可以用什么方式设置超时,如是
搜索到下面这篇文章给客户的开发人员参考:
https://www.iteye.com/blog/shift-alt-ctrl-2314088
很快客户开发人员就从代码里面找到了超时的设置
治标的方法:修改这个超时的配置,将时间改大一点
治本就要分析一下这个SQL,把它进一步优化一下
体会:你看到的不一定是真的,你听到的也不一定是真的,要透过现象看本质!