java - Hibernate starts slow on local dev machine - 1 minute delay between two DEBUG log lines

Question

• When I start a spring boot application with Hikari since some months it takes over a minute for startup.
• I use an OracleXE on my local machine

Logoutput with 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'

I did not remember that I changed anything.

Here are the settings if this could be an issue:

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  

Update after comments

• I set everything to TRACE. But now this time between logging is even faster ;-), just 10 seconds. If I turn it back it's 30 seconds.

• Between the two lines there are a lot of log outputs of org.hibernate.engine.jdbc.env.internal.NormalizingIdentifierHelperImpl

log

 [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 [

Answer 1

等待大神答复