hikari在本地开发人员机器上启动缓慢-两个调试日志行之间延迟1分钟

eqzww0vc  于 2021-06-26  发布在  Java
关注(0)|答案(0)|浏览(1606)

几个月以来,当我用hikari启动一个spring启动应用程序时,启动需要一分钟以上的时间。
我在本地机器上使用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, active=1, idle=0, 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, active=1, 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, active=1, idle=10, 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, active=1, idle=10, 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

评论后更新
我把一切都安排好了。但是现在两次登录之间的时间更短了;-),只有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占用了所有的时间。中间没有Spring的痕迹。

暂无答案!

目前还没有任何答案,快来回答吧!

相关问题