前言
最近做项目，发现老项目出现xxx，这个错误其实很简单，出现在MySQL数据库Server端对长时间没有使用的client连接执行清楚处理，因为是druid数据库，且在github也出现这样的issue：The last packet successfully received from the server was 6,011 milliseconds ago. The last packet sent successfully to the server was 6,011 milliseconds ago.，所以怀疑是不是druid配置的问题，毕竟连接池会定时的检查连接，但是实际排查发现不是那么回事，是连接池泄露了，只不过并发不大，表现为{conn-10002} discard错误而已。
准备
按照笔者上次的文章mybatis plus相同Id与xml配置错误时，mybatis plus解决逻辑_mybatis plus xml文件查询id名字相同-优快云博客
准备数据库，且通过开启root权限
这个是x64的mysql镜像，在M芯片的mac上会报一个黄色叹号提示，说是不能发挥最佳性能，可能有兼容性啥的，实际是可以正常运行的，下面的示例就是用的x64的镜像。同理为了实践arm64镜像arm64v8/mysql
这里我用了最新的镜像
版本是9.2
但是在执行root远程登录时，发现有2条记录，已经不用更新Host，可以直接远程登录连接
demo
demo简单写一下，实际项目肯定复杂很多
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
<version>2.7.17</version>
</dependency>
<dependency>
<groupId>com.alibaba</groupId>
<artifactId>druid-spring-boot-starter</artifactId>
<version>1.2.22</version>
</dependency>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-jdbc</artifactId>
<version>2.7.17</version>
</dependency>
<dependency>
<groupId>org.mybatis.spring.boot</groupId>
<artifactId>mybatis-spring-boot-starter</artifactId>
<version>2.3.2</version>
</dependency>
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>8.0.33</version>
</dependency>
</dependencies>写一个main controller dao
@SpringBootApplication
@MapperScan("org.example.druid.demo.dao")
public class DruidMain {
public static void main(String[] args) {
SpringApplication.run(DruidMain.class, args);
}
}
@RestController
public class DemoController {
@Autowired
private UserDao userDao;
@RequestMapping(value = "/demo", method = RequestMethod.GET)
public String demo(){
int num = userDao.updateUser();
return "{\"update\" : " + num + "}";
}
}
@Mapper
public interface UserDao {
@Update("update User set age = 30 where id = 1")
int updateUser();
}配置文件
spring.datasource.druid.url= jdbc:mysql://127.0.0.1:3306/demo?useUnicode=true&characterEncoding=UTF-8&allowMultiQueries=true&autoReconnect=true&useSSL=false&serverTimezone=Asia/Shanghai
spring.datasource.druid.username= root
spring.datasource.druid.password= 123456i
spring.datasource.druid.driver-class-name= com.mysql.cj.jdbc.Driver
spring.datasource.druid.initialSize=2
spring.datasource.druid.minIdle=2
spring.datasource.druid.maxActive=2
spring.datasource.druid.maxWait=20000
spring.datasource.druid.timeBetweenEvictionRunsMillis=1000
spring.datasource.druid.minEvictableIdleTimeMillis=30000
spring.datasource.druid.validationQuery=SELECT 1
spring.datasource.druid.validationQueryTimeout=1
spring.datasource.druid.testOnBorrow=false
spring.datasource.druid.testOnReturn=false
spring.datasource.druid.testWhileIdle=true
spring.datasource.druid.keepAlive=true
spring.datasource.druid.socketTimeout=6000
spring.datasource.druid.poolPreparedStatements=true
这一步实际上没什么问题，但是如果涉及编程式事务，那么可能出现代码逻辑漏洞
@Configuration
public class DemoConfiguration {
@Bean
public PlatformTransactionManager initPlatformTransactionManager(DruidDataSource dataSource) {
return new DataSourceTransactionManager(dataSource);
}
}
@RestController
public class DemoController {
@Autowired
private UserDao userDao;
@Autowired
private PlatformTransactionManager transactionManager;
@RequestMapping(value = "/demo", method = RequestMethod.GET)
public String demo(){
TransactionStatus transactionStatus = transactionManager.getTransaction(new DefaultTransactionDefinition());
int num = 0;
try {
num = userDao.updateUser();
transactionManager.commit(transactionStatus);
} catch (TransactionException e) {
transactionManager.rollback(transactionStatus);
}
return "{\"update\" : " + num + "}";
}
}这样写也没问题，但是，如果我们在事务拿到后，因为一些逻辑return呢
设置MySQL的超时时间
通过临时设置或者永久设置，--来自bing AI搜索
比如我们临时设置1分钟试试，问题复现
表现为{conn-10002} discard
2025-02-25 21:52:26.692 DEBUG 2129 --- [nio-8080-exec-1] c.a.druid.pool.PreparedStatementPool : {conn-10002, pstmt-20000} exit cache
2025-02-25 21:52:26.695 DEBUG 2129 --- [nio-8080-exec-1] com.alibaba.druid.util.JdbcUtils : close connection error排查过程
The last packet successfully received from the server was 6,006 milliseconds ago. The last packet sent successfully to the server was 6,006 milliseconds ago.
2025-02-25 21:52:26.690 ERROR 2129 --- [nio-8080-exec-1] druid.sql.Statement : {conn-10002, pstmt-20002} execute error. select * from User
com.mysql.cj.jdbc.exceptions.CommunicationsException: The last packet successfully received from the server was 183,457 milliseconds ago. The last packet sent successfully to the server was 183,458 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:175) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:916) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3462) [druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:434) [druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3460) [druid-1.2.22.jar:na]
at com.alibaba.druid.wall.WallFilter.preparedStatement_execute(WallFilter.java:686) [druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3460) [druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:434) [druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3460) [druid-1.2.22.jar:na]
at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.execute(PreparedStatementProxyImpl.java:158) [druid-1.2.22.jar:na]
at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:483) [druid-1.2.22.jar:na]
at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:65) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:80) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:65) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:336) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:158) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:110) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:90) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:154) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:147) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:142) [mybatis-3.5.14.jar:3.5.14]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_431]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_431]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_431]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_431]
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:425) [mybatis-spring-2.1.2.jar:2.1.2]
at com.sun.proxy.$Proxy57.selectList(Unknown Source) [na:na]
at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:224) [mybatis-spring-2.1.2.jar:2.1.2]
at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:147) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:80) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.binding.MapperProxy$PlainMethodInvoker.invoke(MapperProxy.java:141) [mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:86) [mybatis-3.5.14.jar:3.5.14]
at com.sun.proxy.$Proxy61.selectUsers(Unknown Source) [na:na]
at org.example.druid.demo.controller.DemoController.getUsers(DemoController.java:51) [classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_431]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_431]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_431]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_431]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) [spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) [spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1072) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:965) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) [spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) [spring-webmvc-5.3.30.jar:5.3.30]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:529) [tomcat-embed-core-9.0.82.jar:4.0.FR]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) [spring-webmvc-5.3.30.jar:5.3.30]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:623) [tomcat-embed-core-9.0.82.jar:4.0.FR]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:209) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) [tomcat-embed-websocket-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) [spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) [spring-web-5.3.30.jar:5.3.30]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) [spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) [spring-web-5.3.30.jar:5.3.30]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) [spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) [spring-web-5.3.30.jar:5.3.30]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:168) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:390) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:928) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1794) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.82.jar:9.0.82]
at java.lang.Thread.run(Thread.java:750) [na:1.8.0_431]
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: The last packet successfully received from the server was 183,457 milliseconds ago. The last packet sent successfully to the server was 183,458 milliseconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring and/or testing connection validity before use in your application, increasing the server configured values for client timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[na:1.8.0_431]
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[na:1.8.0_431]
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[na:1.8.0_431]
at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[na:1.8.0_431]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:62) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:150) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:166) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:582) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:762) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:701) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1052) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:657) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:893) ~[mysql-connector-j-8.0.33.jar:8.0.33]
... 83 common frames omitted
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:67) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:81) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:576) ~[mysql-connector-j-8.0.33.jar:8.0.33]
... 88 common frames omitted这个问题在github也有类似的情况，但是不一定是笔者遇到的问题：https://github.com/alibaba/druid/issues/5963
对于连接泄露可以配置泄露连接强制回收，但是这个仅在排查问题使用
removeAbandoned: true
removeAbandonedTimeoutMillis: 30000 #(以毫秒数为单位)
logAbandoned: true貌似有用，但是实际情况是占用数据库连接的线程并不一定是问题的代码逻辑，我这里仅仅写了一个controller，刚好对应上
所以排查还需要另外的思路，下面演示解决A的锅B来背的案例。
解决方法
开启连接池连接的状态日志，这里以druid为例
com.alibaba.druid.filter.logging.LogFilter
既然查看连接情况，那么这个最关键
spring.datasource.druid.filters=stat,wall,slf4j
logging.level.com.alibaba.druid=TRACE
#最关键的日志
logging.level.druid.sql.Connection=TRACE
当然笔者使用的MySQL版本8.0，这里是客户端缓存，MySQL8.0已经删除了查询缓存，而且这里是更新操作，毕竟查询缓存命中效率比较低，还是吞吐量比较重要，还增加了查询重写插件
以另一个不是事务的请求为例，用于验证问题
update的连接调用
等待1分钟，并发多次请求查询连接后就会报错
错误日志分析
错误的id为10002，从日志往上追溯
这里就是查询业务背了开始更新业务的锅，毕竟查询没有事务。事务代码BUG导致连接没被连接池回收 ，但被查询业务使用了连接，而且有时候可能和mysql Server的一些超时断掉连接的特性结合，那么问题就复杂了。
找到问题就好处理有问题的代码了，毕竟解决问题很简单，找到问题很难。
连接未超时
上面讲的因为连接事务未释放导致mysql Server连接超时的情况，如果在连接没超时的时候，会发生什么？show me the code
先执行手动事务，不提交，实际上Tomcat的线程池是复用的，数据库连接池事务提交与否，根本不会关注，但是如果事务不提交，这个连接就不会pool-recycle，导致连接池连接泄露。
1、当这个线程执行事务未提交后，实际上线程被回收；
2、线程回收后去执行其他数据库操作，这个时候会出现：
这个线程使用连接池的连接，可以正常执行
这个线程使用以前的未提交或者回滚事务的连接，那么执行异常
2025-03-01 20:01:17.455 INFO 6068 --- [nio-8080-exec-1] o.e.d.demo.controller.DemoController : write user
2025-03-01 20:01:17.459 DEBUG 6068 --- [nio-8080-exec-1] c.a.druid.pool.PreparedStatementPool : {conn-10002, pstmt-20003} enter cache
2025-03-01 20:01:18.348 INFO 6068 --- [nio-8080-exec-2] o.e.d.demo.controller.DemoController : write user
2025-03-01 20:01:18.350 ERROR 6068 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.jdbc.UncategorizedSQLException:
### Error updating database. Cause: java.sql.SQLException: connection disabled
### The error may exist in org/example/druid/demo/dao/UserDao.java (best guess)
### The error may involve org.example.druid.demo.dao.UserDao.insertUser
### The error occurred while executing an update
### SQL: insert into User(age, name) values (33, 'demo')
### Cause: java.sql.SQLException: connection disabled
; uncategorized SQLException; SQL state [null]; error code [0]; connection disabled; nested exception is java.sql.SQLException: connection disabled] with root cause
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method) ~[na:1.8.0_431]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[na:1.8.0_431]
at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[na:1.8.0_431]
at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[na:1.8.0_431]
at com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at java.io.FilterInputStream.read(FilterInputStream.java:133) ~[na:1.8.0_431]
at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:81) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:576) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:762) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:701) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1052) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:657) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:893) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.mysql.cj.jdbc.ClientPreparedStatement.execute(ClientPreparedStatement.java:354) ~[mysql-connector-j-8.0.33.jar:8.0.33]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3462) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:434) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3460) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.wall.WallFilter.preparedStatement_execute(WallFilter.java:686) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3460) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterEventAdapter.preparedStatement_execute(FilterEventAdapter.java:434) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.filter.FilterChainImpl.preparedStatement_execute(FilterChainImpl.java:3460) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.proxy.jdbc.PreparedStatementProxyImpl.execute(PreparedStatementProxyImpl.java:158) ~[druid-1.2.22.jar:na]
at com.alibaba.druid.pool.DruidPooledPreparedStatement.execute(DruidPooledPreparedStatement.java:483) ~[druid-1.2.22.jar:na]
at org.apache.ibatis.executor.statement.PreparedStatementHandler.update(PreparedStatementHandler.java:48) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.statement.RoutingStatementHandler.update(RoutingStatementHandler.java:75) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.SimpleExecutor.doUpdate(SimpleExecutor.java:50) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.BaseExecutor.update(BaseExecutor.java:117) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.executor.CachingExecutor.update(CachingExecutor.java:76) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.session.defaults.DefaultSqlSession.update(DefaultSqlSession.java:197) ~[mybatis-3.5.14.jar:3.5.14]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_431]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_431]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_431]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_431]
at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:425) ~[mybatis-spring-2.1.2.jar:2.1.2]
at com.sun.proxy.$Proxy58.update(Unknown Source) ~[na:na]
at org.mybatis.spring.SqlSessionTemplate.update(SqlSessionTemplate.java:288) ~[mybatis-spring-2.1.2.jar:2.1.2]
at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:67) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.binding.MapperProxy$PlainMethodInvoker.invoke(MapperProxy.java:141) ~[mybatis-3.5.14.jar:3.5.14]
at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:86) ~[mybatis-3.5.14.jar:3.5.14]
at com.sun.proxy.$Proxy63.updateUser(Unknown Source) ~[na:na]
at org.example.druid.demo.controller.DemoController.demo(DemoController.java:39) ~[classes/:na]
at org.example.druid.demo.controller.DemoController$$FastClassBySpringCGLIB$$95a50180.invoke(<generated>) ~[classes/:na]
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218) ~[spring-core-5.3.30.jar:5.3.30]
at org.springframework.aop.framework.CglibAopProxy.invokeMethod(CglibAopProxy.java:386) ~[spring-aop-5.3.30.jar:5.3.30]
at org.springframework.aop.framework.CglibAopProxy.access$000(CglibAopProxy.java:85) ~[spring-aop-5.3.30.jar:5.3.30]
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:703) ~[spring-aop-5.3.30.jar:5.3.30]
at org.example.druid.demo.controller.DemoController$$EnhancerBySpringCGLIB$$62556858.demo(<generated>) ~[classes/:na]
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_431]
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_431]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_431]
at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_431]
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1072) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:965) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.30.jar:5.3.30]
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.30.jar:5.3.30]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:529) ~[tomcat-embed-core-9.0.82.jar:4.0.FR]
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.30.jar:5.3.30]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:623) ~[tomcat-embed-core-9.0.82.jar:4.0.FR]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:209) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:51) ~[tomcat-embed-websocket-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.30.jar:5.3.30]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.30.jar:5.3.30]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.30.jar:5.3.30]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) ~[spring-web-5.3.30.jar:5.3.30]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:178) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:153) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:168) ~[tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:90) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:130) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:93) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:390) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:63) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:928) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1794) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) [tomcat-embed-core-9.0.82.jar:9.0.82]
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.82.jar:9.0.82]
at java.lang.Thread.run(Thread.java:750) [na:1.8.0_431]
这里的connection id是conn-10002，线程id是nio-8080-exec-1，nio-8080-exec-2；
线程nio-8080-exec-1执行没有报错，但是数据库是没有insert成功这条记录的，笔者试了10次，成功8条，最后一条报错，所以判断这2次都没成功，但是一次不报错，一次报错。执行10次（笔者这里是为了复现，刚好10次复现，但是不一定是每次都是10次必现，但是这种情况是必现的）请求结果：只有8条
根据连接id号追根溯源
可以看到
nio-8080-exec-1的线程一直持有conn-10002的连接（事务未提交），当nio-8080-exec-1线程用conn-10002连接做别的事务（Spring声明式事务）时，根据Spring事务传播默认级别，是以原事务为准，原事务是编程式事务，手动提交，所以这里不可能提交成功。
同时当别的线程nio-8080-exec-2来持有这个conn-10002的连接时，报错connection disabled。因为这个连接被nio-8080-exec-1占了。
如果不写注解@Transactional呢，实际上结果也是一样，这里是因为本身dao有自动事务（Spring管理，传播级别也一样）
排查
然后看开始的时候
总结
我们在写代码时，尽量还是使用框架封装的逻辑，比如连接池，比如Spring声明式事务，可以避免编程式事务在写代码时的逻辑漏洞，因为在没触发的时候很难出现，测试很多时候不充分。实际上一起写jdbc的时候还很少出现这个问题，因为那个时候会非常注意连接的回收，事务的提交逻辑，但是Spring自动管理后，这个就很少注意了，因为注解声明式事务太方便了，只有特殊时候才会自己管理事务。
另外这个问题具备隐蔽性，因为报错是MySQL驱动连接MySQL Server报超时未使用关闭连接，但是此处示例的根源却是编程式事务导致连接池泄露，单个问题实际上可以头痛医头，但是当一些mysqlServer的特性加持下，就变成了头痛医脚的感觉了，解决问题很容易，发现问题很难。
扫一扫
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
