当前位置：主页 > 查看内容

记一次生产环境数据库连接超时自动回收问题及解决方法

发布时间：2021-06-06 00:00| 有 位朋友查看

简介：最近在前台导入3000条记录时，经常发现只导入大概500条记录，然后就会报ERROR TransactionInterceptor - Application exception overridden by rollback exception的问题。下面记录一下解决过程，以作备忘! 思路 这里主要是由于连接时间过长，失效所致。即，……

最近在前台导入3000条记录时，经常发现只导入大概500条记录，然后就会报ERROR TransactionInterceptor - Application exception overridden by rollback exception的问题。下面记录一下解决过程，以作备忘!

思路

这里主要是由于连接时间过长，失效所致。即，程序获取到的连接已经失效了，而拿一个失效的连接再次请求就会报那样的异常。

1. 查看应用日志

可以看到都是在跟后端数据库连接时断开导致。

记一次生产环境数据库连接超时自动回收问题及解决方法

具体信息如下：

  1. java.sql.SQLNonTransientConnectionException: No operations allowed after connection closed. 
  2.     at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:110) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  3.     at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:97) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  4.     at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:89) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  5.     at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:63) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  6.     at com.mysql.cj.jdbc.exceptions.SQLError.createSQLException(SQLError.java:73) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  7.     at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:73) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  8.     at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1875) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  9.     at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:370) ~[HikariCP-3.2.0.jar!/:na] 
  10.     at com.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java) [HikariCP-3.2.0.jar!/:na] 
  11.     at org.springframework.jdbc.datasource.DataSourceTransactionManager.doRollback(DataSourceTransactionManager.java:344) [spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  12.     at org.springframework.transaction.support.AbstractPlatformTransactionManager.processRollback(AbstractPlatformTransactionManager.java:838) [spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  13.     at org.springframework.transaction.support.AbstractPlatformTransactionManager.rollback(AbstractPlatformTransactionManager.java:812) [spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  14.     at org.springframework.transaction.support.TransactionTemplate.rollbackOnException(TransactionTemplate.java:168) [spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  15.     at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:144) [spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  16.     at logwire.web.service.ActionContext$TransactionExecutor.doWithoutResult(ActionContext.java:716) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  17.     at logwire.web.service.ActionContext.doInNewTransactionWithoutResult(ActionContext.java:561) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  18.     at logwire.web.service.task.run.impl.DefaultTaskRunner.doTaskInner(DefaultTaskRunner.java:85) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  19.     at logwire.web.service.task.run.impl.DefaultTaskRunner.doTaskInnerWithMetric(DefaultTaskRunner.java:130) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  20.     at logwire.web.service.task.run.impl.DefaultTaskRunner.doTask(DefaultTaskRunner.java:176) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  21.     at logwire.web.service.task.execute.TaskExecuteService.doTask(TaskExecuteService.java:35) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  22.     at logwire.web.service.task.execute.redisson.impl.RedissonTaskImpl.doTask(RedissonTaskImpl.java:22) [logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  23.     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_102] 
  24.     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_102] 
  25.     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_102] 
  26.     at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_102] 
  27.     at org.redisson.RedissonRemoteService.invokeMethod(RedissonRemoteService.java:360) [redisson-3.11.3.jar!/:3.11.3] 
  28.     at org.redisson.RedissonRemoteService.lambda$executeMethod$4(RedissonRemoteService.java:329) [redisson-3.11.3.jar!/:3.11.3] 
  29.     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_102] 
  30.     at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_102] 
  31.     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_102] 
  32.     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_102] 
  33.     at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_102] 
  34. Caused by: com.mysql.cj.exceptions.ConnectionIsClosedException: No operations allowed after connection closed. 
  35.     at sun.reflect.GeneratedConstructorAccessor129.newInstance(Unknown Source) ~[na:na] 
  36.     at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_102] 
  37.     at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_102] 
  38.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  39.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  40.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  41.     at com.mysql.cj.NativeSession.checkClosed(NativeSession.java:1259) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  42.     at com.mysql.cj.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:575) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  43.     at com.mysql.cj.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:1829) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  44.     ... 25 common frames omitted 
  45. Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure 
  46.  
  47. The last packet successfully received from the server was 35,661 milliseconds ago. The last packet sent successfully to the server was 35,662 milliseconds ago. 
  48.     at sun.reflect.GeneratedConstructorAccessor126.newInstance(Unknown Source) ~[na:na] 
  49.     at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_102] 
  50.     at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_102] 
  51.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  52.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  53.     at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  54.     at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  55.     at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:555) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  56.     at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:725) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  57.     at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:664) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  58.     at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:979) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  59.     at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1153) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  60.     at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:951) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  61.     at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1113) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  62.     at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdateInternal(ClientPreparedStatement.java:1061) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  63.     at com.mysql.cj.jdbc.ClientPreparedStatement.executeLargeUpdate(ClientPreparedStatement.java:1381) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  64.     at com.mysql.cj.jdbc.ClientPreparedStatement.executeUpdate(ClientPreparedStatement.java:1046) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  65.     at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61) ~[HikariCP-3.2.0.jar!/:na] 
  66.     at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java) ~[HikariCP-3.2.0.jar!/:na] 
  67.     at org.springframework.jdbc.core.JdbcTemplate.lambda$update$0(JdbcTemplate.java:867) ~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  68.     at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:617) ~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  69.     at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:862) ~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  70.     at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:917) ~[spring-jdbc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  71.     at logwire.web.service.query.sql.QueryDataSetManager.insertModelRow(QueryDataSetManager.java:419) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  72.     at logwire.web.service.query.sql.QueryDataSetManager.saveModelDataSet(QueryDataSetManager.java:140) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  73.     at logwire.web.service.query.sql.QueryDataSetManager.saveModelDataSet(QueryDataSetManager.java:104) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  74.     at logwire.web.service.query.sql.QueryDataSetManager.insert(QueryDataSetManager.java:272) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  75.     at logwire.web.service.query.QueryService.insert(QueryService.java:183) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  76.     at logwire.web.service.query.QueryService.insert(QueryService.java:163) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  77.     at jdk.nashorn.internal.scripts.Script$Recompilation$203$16161AAAAAAA$importHandlers.L:1$insertLog(config/custom_js/importHandlers.js:449) ~[na:na] 
  78.     at jdk.nashorn.internal.scripts.Script$Recompilation$198$9472A$tasks.L:1$handleImport$L:256(config/custom_js/tasks.js:273) ~[na:na] 
  79.     at jdk.nashorn.javaadapters.java.util.function.Consumer.accept(Unknown Source) ~[na:na] 
  80.     at java.util.ArrayList.forEach(ArrayList.java:1249) ~[na:1.8.0_102] 
  81.     at jdk.nashorn.internal.scripts.Script$Recompilation$196$9015AAA$tasks.L:1$handleImport(config/custom_js/tasks.js:256) ~[na:na] 
  82.     at jdk.nashorn.internal.scripts.Script$Recompilation$195$8841AAA$tasks.L:1$partsImportDD(config/custom_js/tasks.js:239) ~[na:na] 
  83.     at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:643) ~[nashorn.jar:na] 
  84.     at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494) ~[nashorn.jar:na] 
  85.     at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393) ~[nashorn.jar:na] 
  86.     at jdk.nashorn.api.scripting.ScriptObjectMirror.callMember(ScriptObjectMirror.java:199) ~[nashorn.jar:na] 
  87.     at logwire.core.meta.task.ScriptTask.doTask(ScriptTask.java:24) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  88.     at logwire.web.service.task.run.impl.DefaultTaskRunner$1.doInTransactionWithoutResult(DefaultTaskRunner.java:88) ~[logwire-web-1.0-SNAPSHOT.jar!/:1.0-SNAPSHOT] 
  89.     at org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:36) ~[spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  90.     at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) [spring-tx-5.1.5.RELEASE.jar!/:5.1.5.RELEASE] 
  91.     ... 18 common frames omitted 
  92. Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost. 
  93.     at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:67) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  94.     at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  95.     at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  96.     at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  97.     at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  98.     at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  99.     at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  100.     at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:549) ~[mysql-connector-java-8.0.13.jar!/:8.0.13] 
  101.     ... 53 common frames omitted 

2. 直连mysql测试

由于后端数据库是用mycat+mysql主从做的读写分离，影响因素比较多，所以需先去掉影响的一些因素，这里先直连mysql数据库测试，绕过mycat。

经过业务测试发现可以导入成功，这样问题就在mycat上了。

记一次生产环境数据库连接超时自动回收问题及解决方法

3. mycat关闭读写分离

关闭mycat的读写分离后导入3000条可以导入2700条，但还有部分失败。

mycat日志如下：

  1. INFO [$_NIOREACTOR-1-RW] (io.mycat.net.AbstractConnection.close(AbstractConnection.java:520)) - close connection,reason:stream closed ,ServerConnection [id=55, schema=tms_prod, host=, u 
  2. ser=root,txIsolation=3, autocommit=true, schema=tms_prod, executeSql=null] 
  3. INFO [$_NIOREACTOR-2-RW] (io.mycat.net.AbstractConnection.close(AbstractConnection.java:520)) - close connection,reason:stream closed ,ServerConnection [id=56, schema=tms_prod, host=, u 

4、. 改应用配置

经过查找资料和分析，得出该问题主要是由于连接时间过长，失效所致，既然程序获取的连接已经失效了，那么对于失效的连接就不应该使用，而应该再次获取有效的连接。增加配置如下：

记一次生产环境数据库连接超时自动回收问题及解决方法

  1. spring.datasource.validation-query=SELECT 1 

修改后让业务重新测试，导入正常，问题解决。

总结

当数据库连接池中的连接被创建而长时间不使用的情况下，该连接会自动回收并失效，但客户端并不知道，在进行数据库操作时仍然使用的是无效的数据库连接，这样，就导致客户端程序报“ java.sql.SQLException: Io 异常: Connection reset by peer”或“java.sql.SQLException 关闭的连接”异常，加上spring.datasource.validation-query=SELECT 1配置后，客户端在使用一个无效的连接时会先对该连接进行测试，如果发现该连接已经无效，则重新从连接池获取有效数据库连接来使用。


本文转载自网络，原文链接：https://www.toutiao.com/i6764344273111351815/
本站部分内容转载于网络，版权归原作者所有，转载之目的在于传播更多优秀技术内容，如有侵权请联系QQ/微信：153890879删除，谢谢！
上一篇：分享一份MySQL一键优化脚本，值得收藏 下一篇：10款好用的MySQL GUI工具，数据库管理员的好帮手

推荐图文

  • 周排行
  • 月排行
  • 总排行

随机推荐