问题背景
运营人员在系统选择了一批数据,然后提交请求处理,一段时间后,运营找到开发说,我提交的数据一部分成功了,剩下的一部分还在处理中状态,一直没有更新。
定位分析思路
通过kibana
日志追踪(代码中业务日志),如图,请求的确是已受理,并且依赖的微服务也返回了结果,但是最终修改数据库对应数据的状态却没执行!
Timev message 修改订单案件状态为提交成功:[[1cf84055-9a0b-4b79-ac77-824f5572d732]] 成功 修改订单案件状态为提交成功:「50f08238f-758a-41b1-a8ef-f8590684cc44,29e8838f-bb16-4bcf-9599-dcaf456a3afc,2498bfe0-1598-41c7-ad60-aebe42cdc79c, 144d3c1a-d7db 4101-8f5e-fd67fdf8bbd1,2db04af1-ce96-47c4-9667-a1e4b7f395d1,3312667f-f503-4622-bc51-641e4189f582,250ac540-f7e3-49b4-a2fd-d43eb275ffa9]阳稀十掘金技术社区
起初以为是代码问题,但是再次code review
并没有发现问题,而且运营也说了部分成功,让他们再次操作也都再次成功了。那么既然review代码没有发现问题,就再看看日志,是否有其他错误出现。
从代码发现log.info()
日志后,下一步就是更新数据操作,所以便想到查看周围日志了解情况,点击这里,如图
修改订单案件状态为提交成功:「[0f08238f-758a-41b1-a8ef-f8590684cc44,29e8838f-bb16-4bcf-9599-dcaf456a3afc,2498bfe0-1598-41c7-ad60-aebe42cdc79c, 144d3c1a-d7db 4101-8f5e-fd67fdf8bhd1,2db04af1-ce96-47c4-9667-a1e4h7f395d1,3312667f-f503-4622-hc51-641e4189f582,250ac540-f7e3-49h4-a2fd-d43eh275ffa91
发现一个附近有一个error log
discard connection com.mysq1.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure The 1ast packet successfully received from the server was 1,927,021milliseconds ago.The 1ast packet sent successfully to the server was 0 milliseconds ago atsun.reflect.GeneratedConstructorAccessor276.newInstance(Unknown Source) atsun.reflect.DelegatingConstructorAccessorImp1.newInstance(DelegatingConstructorAccessorImp1.java:45) atjava.1ang.reflect.Constructor.newInstance(Constructor.java:423) 成功,修改订单案件状态为提交成功:b L43Raf_f8r 4cc44, _hhig_thef ocon .7db-4101 47c4-9667-a1 --7f-f503-4022
来分析一下这段话的意思:
discard connection: 丢起连接 Communications link failure:通信链路故障 he last packet successfully received from the server was 1,927,021 milliseconds ago. The last packet sent successfully to the server was 0 milliseconds ago: 它最后一次成功收到来自服务器(mysql server)的数据包是在1,927,021毫秒之前。最后一个成功发送到服务器的报文是0毫秒之前 复制代码
解决问题
错误的原因:MySQL服务在长时间不连接之后断开了,断开之后的首次请求会抛出这个异常
- 检查你的数据库连接地址(配置文件中的url)是否正确.
- 重启应用程序。(不建议,治标不治本)
- mysql5以前的版本可以直接在jdbc连接url的配置中附加上
autoReconnect=true
。 - 查看和连接mysql时间有关的系统变量:
show variables like '%timeout%'
- interactive_timeout:默认值:28800秒(8小时) 服务器关闭交互式连接前,等待活动的秒数。(交互式客户端定义为在mysql_real_connect()中使用CLIENT_INTERACTIVE选项的客户端)
- wait_timeout:默认值:28800秒(8小时) 服务器关闭非交互连接之前,等待活动的秒数。在线程启动时,根据全局
wait_timeout
值或全局interactive_timeout
值初始化会话wait_timeout
值,取决于客户端类型(由mysql_real_connect()的连接选项CLIENT_INTERACTIVE定义)。
如果在wait_timeout
秒期间内,数据库连接(java.sql.Connection)
一直处于等待状态,mysql5就将该连接关闭。这时,你的Java应用的连接池仍然合法地持有该连接的引用。当用该连接来进行数据库操作时,就碰到上述错误。
- 将mysql的全局变量
wait_timeout
的值修改为最大。查看mysql5的手册,发现windows和linux下wait_timeout
的最大值分别是24天和365天。
- 在文件my.ini的最后增加一行:wait_timeout=1814400。(该文件,windows下在mysql的安装目录下,linux下位置为/etc/my.ini)
- 重启mysql。
- 如果经过了以上的步骤,你的问题依旧没有的到解决,则建议你修改下你程序中的mysql驱动的版本。
扩展知识
mysql JDBC URL格式
jdbc:mysql://[host:port],[host:port].../[database][?参数名1][=参数值1][&参数名2][=参数值2]...
在使用数据库连接池的情况下,最好设置如下两个参数
autoReconnect=true&failOverReadOnly=false
mysql与jdbc的操作文档
连接泄漏问题
从连接池中获取连接使用后忘记了连接的关闭,这样连池的连接就会逐渐达到maxActive直至连接池无法提供服务。可以使用如下方式避免该问题发生:
#对于建立连接过长的连接强制关闭 druid.removeAbandoned:true #如果连接建立时间超过了30分钟,则强制将其关闭 druid.removeAbandonedTimeout:1800 #将当前关闭动作记录到日志 druid.logAbandoned:true 复制代码
removeAbandoned
是连接池的高级功能,理论上这中配置不应该出现在实际的生产环境,因为有时应用程序执行长事务,可能这种情况下,会被连接池误回收,该种配置一般在程序测试阶段,为了定位连接泄漏的具体代码位置,被开启。生产环境中连接的关闭应该靠程序自己保证。