问题描述
- 几个月以来，当我使用 Hikari 启动 Spring Boot 应用程序时，启动时间超过一分钟。
- 我在本地机器上使用 OracleXE
使用 com.zaxxer: TRACE 的日志输出
2021-01-05 17:21:17.187 INFO 24412 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Starting...
2021-01-05 17:21:17.192 WARN 24412 --- [ main] com.zaxxer.hikari.util.DriverDataSource : Registered driver with driverClassName=oracle.jdbc.driver.OracleDriver was not found,trying direct instantiation.
2021-01-05 17:21:17.192 DEBUG 24412 --- [ main] com.zaxxer.hikari.util.DriverDataSource : Driver class oracle.jdbc.driver.OracleDriver found in Thread context class loader sun.misc.Launcher$AppClassLoader@3339ad8e
2021-01-05 17:21:17.557 INFO 24412 --- [ main] com.zaxxer.hikari.pool.PoolBase : HikariPool-1 - Driver does not support get/set network timeout for connections. (oracle.jdbc.driver.T4CConnection.getNetworkTimeout()I)
2021-01-05 17:21:17.560 DEBUG 24412 --- [ main] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@220cda54
2021-01-05 17:21:17.562 INFO 24412 --- [ main] com.zaxxer.hikari.HikariDataSource : HikariPool-1 - Start completed.
2021-01-05 17:21:17.596 INFO 24412 --- [ main] org.hibernate.dialect.Dialect : HHH000400: Using dialect: org.hibernate.dialect.Oracle10gDialect
2021-01-05 17:21:17.664 DEBUG 24412 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=1,active=1,idle=0,waiting=0)
2021-01-05 17:21:17.664 DEBUG 24412 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=1,waiting=0)
2021-01-05 17:21:17.691 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@193c4d19
2021-01-05 17:21:17.713 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@17fba04e
2021-01-05 17:21:17.736 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@13c42669
2021-01-05 17:21:17.760 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@56c6aa75
2021-01-05 17:21:17.785 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@2de97131
2021-01-05 17:21:17.806 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@67da5d12
2021-01-05 17:21:17.829 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@551fd8ee
2021-01-05 17:21:17.852 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@50efda2f
2021-01-05 17:21:17.873 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@65e83fed
2021-01-05 17:21:17.895 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Added connection oracle.jdbc.driver.T4CConnection@4e1b5316
2021-01-05 17:21:17.896 DEBUG 24412 --- [onnection adder] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After adding stats (total=11,idle=10,waiting=0)
2021-01-05 17:21:47.667 DEBUG 24412 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Before cleanup stats (total=11,waiting=0)
2021-01-05 17:21:47.667 DEBUG 24412 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - After cleanup stats (total=11,waiting=0)
2021-01-05 17:21:47.667 DEBUG 24412 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool : HikariPool-1 - Fill pool skipped,pool is at sufficient level.
// what happens in this minue? ??????????????????????
2021-01-05 17:21:58.940 WARN 24412 --- [ main] org.hibernate.cfg.AnnotationBinder : HHH000138: Mixing inheritance strategy in a entity hierarchy is not allowed,ignoring sub strategy in: org.account.AccountEntity
2021-01-05 17:22:03.225 INFO 24412 --- [ main] o.h.e.t.j.p.i.JtaPlatformInitiator : HHH000490: Using JtaPlatform implementation: [org.hibernate.engine.transaction.jta.platform.internal.NoJtaPlatform]
2021-01-05 17:22:03.238 INFO 24412 --- [ main] j.LocalContainerEntityManagerfactorybean : Initialized JPA EntityManagerFactory for persistence unit 'core'
我不记得我改变了什么。
以下是设置，如果这可能是一个问题：
2021-01-05 17:21:17.180 WARN 24412 --- [ main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - idleTimeout is less than 10000ms,setting to default 600000ms.
2021-01-05 17:21:17.181 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : HikariPool-1 - configuration:
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : allowPoolSuspension.............false
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : autoCommit......................true
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : catalog.........................none
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : connectionInitsql...............none
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : connectionTestQuery.............none
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : connectionTimeout...............30000
2021-01-05 17:21:17.183 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : dataSource......................none
2021-01-05 17:21:17.184 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : dataSourceClassName.............none
2021-01-05 17:21:17.184 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : dataSourceJNDI..................none
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : driverClassName................."oracle.jdbc.driver.OracleDriver"
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : exceptionOverrideClassName......none
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : healthCheckProperties...........{}
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : healthCheckRegistry.............none
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : idleTimeout.....................600000
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : initializationFailTimeout.......1
2021-01-05 17:21:17.185 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : isolateInternalQueries..........false
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : jdbcUrl.........................jdbc:oracle:thin:@localhost:1521:XE
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : leakDetectionThreshold..........120000
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : maxLifetime.....................1800000
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : maximumPoolSize.................20
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : metricRegistry..................none
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : metricsTrackerFactory...........none
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : minimumIdle.....................10
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : poolName........................"HikariPool-1"
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : readOnly........................false
2021-01-05 17:21:17.186 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : registerMbeans..................false
2021-01-05 17:21:17.187 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : scheduledExecutor...............none
2021-01-05 17:21:17.187 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : schema..........................none
2021-01-05 17:21:17.187 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : threadFactory...................internal
2021-01-05 17:21:17.187 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : transactionIsolation............default
2021-01-05 17:21:17.187 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : username........................"user"
2021-01-05 17:21:17.187 DEBUG 24412 --- [ main] com.zaxxer.hikari.HikariConfig : validationTimeout...............5000
2021-01-05 17:21:17.187 INFO 24412 --- [ main] com.zaxxer.hikari.HikariDataSource
评论后更新
-
我将所有内容都设置为 TRACE。但现在这次记录之间的时间更快了;-)，只需 10 秒。如果我把它转回来，那就是 30 秒。
-
这两行之间有很多
的日志输出org.hibernate.engine.jdbc.env.internal.normalizingIdentifierHelperImpl
日志
[2m2021-01-06 09:26:26.172[0;39m [32mDEBUG[0;39m [35m13048[0;39m [2m---[0;39m [2m[l-1 housekeeper][0;39m [36mcom.zaxxer.hikari.pool.HikariPool [0;39m [2m:[0;39m HikariPool-1 - Fill pool skipped,pool is at sufficient level.
--start of long wait time
[2m2021-01-06 09:26:34.161[0;39m [32mTRACE[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36m.e.j.e.i.normalizingIdentifierHelperImpl[0;39m [2m:[0;39m normalizing identifier quoting [null]
[2m2021-01-06 09:26:37.903[0;39m [32mTRACE[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36m.e.j.e.i.normalizingIdentifierHelperImpl[0;39m [2m:[0;39m normalizing identifier quoting [null]
[2m2021-01-06 09:26:37.903[0;39m [32mTRACE[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36m.e.j.e.i.normalizingIdentifierHelperImpl[0;39m [2m:[0;39m normalizing identifier quoting [null]
[2m2021-01-06 09:26:37.903[0;39m [32mTRACE[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36m.e.j.e.i.normalizingIdentifierHelperImpl[0;39m [2m:[0;39m normalizing identifier quoting [AUDIT_TRAIL$_SEQ]
[2m2021-01-06 09:26:37.904[0;39m [32mTRACE[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36m.e.j.e.i.normalizingIdentifierHelperImpl[0;39m [2m:[0;39m normalizing identifier quoting [null]
...
...
[2m2021-01-06 09:26:37.943[0;39m [32mTRACE[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36mo.h.s.i.AbstractServiceRegistryImpl [0;39m [2m:[0;39m Initializing service [role=org.hibernate.engine.jdbc.spi.JdbcServices]
[2m2021-01-06 09:26:37.947[0;39m [32mDEBUG[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36mo.h.boot.model.relational.Namespace [0;39m [2m:[0;39m Created database namespace [logicalName=Name{catalog=null,schema=null},physicalName=Name{catalog=null,schema=null}]
[2m2021-01-06 09:26:37.953[0;39m [32mDEBUG[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36mo.h.type.spi.TypeConfiguration$Scope [0;39m [2m:[0;39m scoping TypeConfiguration [org.hibernate.type.spi.TypeConfiguration@261b6c8c] to MetadataBuildingContext [org.hibernate.boot.internal.MetadataBuildingContextRootImpl@2dcbf825]
--end of long wait time
[2m2021-01-06 09:26:38.054[0;39m [33m WARN[0;39m [35m13048[0;39m [2m---[0;39m [2m[main][0;39m [36morg.hibernate.cfg.AnnotationBinder [0;39m [2m:[0;39m HHH000138: Mixing inheritance strategy in a entity hierarchy is not allowed,ignoring sub strategy in: com.core.domain.account.AccountEntity
所以看起来 hibernate normalizingIdentifierHelperImpl 一直在花时间。中间没有春天的痕迹。
解决方法
暂无找到可以解决该程序问题的有效方法，小编努力寻找整理中！
如果你已经找到好的解决方法，欢迎将解决方案带上本链接一起发送给小编。
小编邮箱:dio#foxmail.com (将#修改为@）