search

baomidou / dynamic-datasource

dynamic datasource for springboot 多数据源 动态数据源 主从分离 读写分离 分布式事务
https://www.kancloud.cn/tracy5546/dynamic-datasource/2264611
Apache License 2.0
4.75k stars 1.19k forks source link

通过spring-boot-starter-actuator关闭项目出现线程警告 #588

Closed git-yqk closed 10 months ago

git-yqk commented 1 year ago

Enviroment

JDK Version(required): OracleJDK_1.8.201

SpringBoot Version(required): 2.7.17

dynamic-datasource-spring-boot-starter Version(required): 4.2.0

Describe what happened

使用 http://127.0.0.1:8080/actuator/shutdown 关闭Springboot时会出现警告

Expected Result: 正常关闭项目

Actual Result: 项目可以关闭，但会出现线程警告

If there is an exception,or aop invalid,please attach the exception trace:

2023-11-09 16:19:35.662  INFO 1824 --- [           main] com.gznyqx.drought.DroughtApplication    : {"message":"Shutting down, bye..."}
2023-11-09 16:19:36.880  INFO 1824 --- [      Thread-19] o.apache.catalina.core.StandardService   : Stopping service [Tomcat]
2023-11-09 16:19:36.881  INFO 1824 --- [      Thread-19] o.a.c.c.C.[Tomcat].[localhost].[/]       : Destroying Spring FrameworkServlet 'dispatcherServlet'
2023-11-09 16:19:36.883  WARN 1824 --- [      Thread-19] o.a.c.loader.WebappClassLoaderBase       : The web application [ROOT] appears to have started a thread named [STDB housekeeper] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 java.lang.Thread.run(Thread.java:748)
2023-11-09 16:19:36.884  WARN 1824 --- [      Thread-19] o.a.c.loader.WebappClassLoaderBase       : The web application [ROOT] appears to have started a thread named [FIDB housekeeper] but has failed to stop it. This is very likely to create a memory leak. Stack trace of thread:
 sun.misc.Unsafe.park(Native Method)
 java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
 java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
 java.lang.Thread.run(Thread.java:748)
2023-11-09 16:19:36.894  INFO 1824 --- [      Thread-19] c.b.d.d.DynamicRoutingDataSource         : dynamic-datasource start closing ....
2023-11-09 16:19:36.896  INFO 1824 --- [      Thread-19] com.zaxxer.hikari.HikariDataSource       : FIDB - Shutdown initiated...
2023-11-09 16:19:36.900  INFO 1824 --- [      Thread-19] com.zaxxer.hikari.HikariDataSource       : FIDB - Shutdown completed.
2023-11-09 16:19:36.901  INFO 1824 --- [      Thread-19] c.b.d.d.d.DefaultDataSourceDestroyer     : dynamic-datasource close the datasource named [FIDB] success,
2023-11-09 16:19:36.901  INFO 1824 --- [      Thread-19] com.zaxxer.hikari.HikariDataSource       : STDB - Shutdown initiated...
2023-11-09 16:19:36.903  INFO 1824 --- [      Thread-19] com.zaxxer.hikari.HikariDataSource       : STDB - Shutdown completed.
2023-11-09 16:19:36.903  INFO 1824 --- [      Thread-19] c.b.d.d.d.DefaultDataSourceDestroyer     : dynamic-datasource close the datasource named [STDB] success,
2023-11-09 16:19:36.903  INFO 1824 --- [      Thread-19] c.b.d.d.DynamicRoutingDataSource         : dynamic-datasource all closed success,bye

Steps to reproduce

huayanYu commented 1 year ago

无法根据步骤请求 2023-11-10 09:50:38.734 WARN 46214 --- [nio-8080-exec-5] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.web.HttpRequestMethodNotSupportedException: Request method 'GET' not supported]

https://github.com/dynamic-datasource/dynamic-datasource-samples/tree/master/orm-samples/mybatis-sample

git-yqk commented 1 year ago

无法根据步骤请求 2023-11-10 09：50：38.734 WARN 46214 --- [nio-8080-exec-5] .w.s.m.s.DefaultHandlerExceptionResolver：已解决 [org.springframework.web.HttpRequestMethodNotSupportedException：不支持请求方法“GET”]

https://github.com/dynamic-datasource/dynamic-datasource-samples/tree/master/orm-samples/mybatis-sample

请在终端使用 curl http://127.0.0.1:8080/actuator/shutdown -X POST 或使用API测试工具发送POST请求。 连接池为HikariCP-4.0.3，ORM为Mybatis-Plus-3.5.4.1。

huayanYu commented 1 year ago

@alvinkwok1 look

alvinkwok1 commented 1 year ago

我周日排查下

alvinkwok1 commented 1 year ago

@huayanYu @git-yqk 有排查结果了。在使用actuator进行应用关闭的时候，会调用org.apache.catalina.loader.WebappClassLoaderBase的stop方法，该方法将会关闭掉现在所有运行的线程，其中对线程的ClassLoader会做检查， DynamicDataSource的HikariDataSource的加载ClassLoader是基于 WebappClassLoaderBase的子类，因此在关闭过程中会出现告警。 具体代码见： org.apache.catalina.loader.WebappClassLoaderBase#clearReferencesThreads

我对比了SpringBoot的DataSourceConfiguration对HikariCP的创建过程，发现在创建过程中指定了ClassLoader来加载HikariCp来加载对应的DataSource。

总的来说，这个告警问题不影响功能，如果要解决掉这个告警问题需要使用特定加载器完成，可参考DataSourceConfiguration对数据源的加载。

huayanYu commented 1 year ago

哦,等我研究下.

huayanYu commented 12 months ago

@huayanYu @git-yqk 有排查结果了。在使用actuator进行应用关闭的时候，会调用org.apache.catalina.loader.WebappClassLoaderBase的stop方法，该方法将会关闭掉现在所有运行的线程，其中对线程的ClassLoader会做检查， DynamicDataSource的HikariDataSource的加载ClassLoader是基于 WebappClassLoaderBase的子类，因此在关闭过程中会出现告警。 具体代码见： org.apache.catalina.loader.WebappClassLoaderBase#clearReferencesThreads

我对比了SpringBoot的DataSourceConfiguration对HikariCP的创建过程，发现在创建过程中指定了ClassLoader来加载HikariCp来加载对应的DataSource。

总的来说，这个告警问题不影响功能，如果要解决掉这个告警问题需要使用特定加载器完成，可参考DataSourceConfiguration对数据源的加载。

@alvinkwok1 我没有找到指定classLoader创建的代码也, 都是 protected static T createDataSource(DataSourceProperties properties, Class<? extends DataSource> type) { return (T) properties.initializeDataSourceBuilder().type(type).build(); } .build里也没发现啊

alvinkwok1 commented 12 months ago

@huayanYu 抱歉，我的排查过程是错误的，根据你的提示我重新看了一遍代码，有几点错误：

  1. 我的源代码版本下载使用的是springboot3.0的，调试过程中不太确定为什么指向了这个版本的代码；
  2. 我错误的理解为thread创建过程使用的classLoader是创建类所用的classLoader（应该是看源码的时候看错了），实际上采取的是Thread.currentThread(）的contextClassLoader

对比了dynamic-datasource和spring创建连接池的区别，dynamic-datasource是立即创建的连接池，这个时候的线程的classLoader是Tomcat的classLoader，而spring的数据源创建并不是立即创建的，而是atacor对应的RMI线程进行连接检测的时候创建的,此时的线程的classLoader不是tomcat的classLoader。

alvinkwok1 commented 12 months ago

能力有限，只能排查到这儿了， 后续我看了下普通的bean的加载并未使用tomcat的classLoader，并不清楚 为什么会有这样的差异，不知道是不是因为dynamic-datasource的注入方式导致的