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

运维 数据库运维
最近在前台导入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=55schema=tms_prodhost=, u 
  2. ser=root,txIsolation=3autocommit=trueschema=tms_prodexecuteSql=null
  3. INFO [$_NIOREACTOR-2-RW] (io.mycat.net.AbstractConnection.close(AbstractConnection.java:520)) - close connection,reason:stream closed ,ServerConnection [id=56schema=tms_prodhost=, 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配置后,客户端在使用一个无效的连接时会先对该连接进行测试,如果发现该连接已经无效,则重新从连接池获取有效数据库连接来使用。

 

责任编辑:赵宁宁 来源: 今日头条
相关推荐

2018-12-06 16:25:39

数据库服务器线程池

2021-03-01 06:14:50

环境高并发延迟

2019-11-18 13:42:55

MySQL数据库迁移

2019-08-19 01:34:38

数据库SQL数据库优化

2019-11-22 08:05:01

数据库mysql分区

2019-12-12 10:38:10

mysql数据库nnodb

2021-10-14 10:53:20

数据库查询超时

2019-12-27 10:43:48

磁盘数据库死锁

2019-09-08 17:52:10

数据库log file sy等待事件

2019-09-27 17:24:26

数据库优化sql

2019-07-25 08:30:58

数据库服务器故障

2019-09-05 09:17:37

MySQL数据库线程

2019-09-24 07:00:01

SQL Server服务器卡顿内存分配

2019-12-16 07:18:42

数据库SQL代码

2019-08-15 11:30:06

SQL数据库ASH

2018-07-18 15:37:24

数据库DB2故障处理

2020-09-25 07:57:42

生产事故系统

2020-11-03 07:34:12

Kafka后端工程师

2022-06-01 06:17:42

微服务Kafka

2021-01-12 07:57:36

MySQLBinlog故障处理
点赞
收藏

51CTO技术栈公众号