DSLContext bean takes several minutes to be created

Question

After incorporating JOOQ into my Spring-Boot application, the internal Tomcat server boot time is more than 5 minutes!

I configured my application with JOOQ like documented on the Spring Boot documentation.

When I enable 'debug' logging you can notice it takes about 5 minutes for creating bean 'dslContext'. It seems that HikariCP is doing some stuff in the background for several minutes. This didn't happen before I configured JOOQ in my application.

Debug logging below:

21:04:59.292 [           main] DEBUG --- Creating shared instance of singleton bean 'dslContext'
21:04:59.292 [           main] DEBUG --- Creating instance of bean 'dslContext'
21:04:59.292 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
21:04:59.292 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.retry.annotation.RetryConfiguration'
21:04:59.292 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
21:04:59.293 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor'
21:04:59.293 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.boot.autoconfigure.jooq.JooqAutoConfiguration$DslContextConfiguration'
21:04:59.299 [           main] DEBUG --- Creating shared instance of singleton bean 'jooqConfiguration'
21:04:59.300 [           main] DEBUG --- Creating instance of bean 'jooqConfiguration'
21:04:59.300 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
21:04:59.300 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.retry.annotation.RetryConfiguration'
21:04:59.300 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
21:04:59.300 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor'
21:04:59.301 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.boot.autoconfigure.jooq.JooqAutoConfiguration$DslContextConfiguration'
21:04:59.376 [           main] DEBUG --- Eagerly caching bean 'jooqConfiguration' to allow for resolving potential circular references
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.retry.annotation.RetryConfiguration'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.retry.annotation.RetryConfiguration'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
21:04:59.386 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor'
21:04:59.551 [           main] DEBUG --- Finished creating instance of bean 'jooqConfiguration'
21:04:59.562 [           main] DEBUG --- Autowiring by type from bean name 'dslContext' via factory method to bean named 'jooqConfiguration'
21:04:59.942 [           main] DEBUG --- Eagerly caching bean 'dslContext' to allow for resolving potential circular references
21:05:00.023 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
21:05:00.023 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.retry.annotation.RetryConfiguration'
21:05:00.023 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
21:05:00.027 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor'
21:05:00.027 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.cache.config.internalCacheAdvisor'
21:05:00.027 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.retry.annotation.RetryConfiguration'
21:05:00.027 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
21:05:00.027 [           main] DEBUG --- Returning cached instance of singleton bean 'org.springframework.security.methodSecurityMetadataSourceAdvisor'
21:05:20.109 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:05:50.113 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:06:20.114 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:06:50.116 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:07:13.126 [Engine[Tomcat]]] DEBUG --- Start expire sessions StandardManager at 1520539633101 sessioncount 0
21:07:13.128 [Engine[Tomcat]]] DEBUG --- End expire sessions StandardManager processingTime 27 expired sessions: 0
21:07:20.118 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:07:50.121 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:08:20.124 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:08:50.126 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:09:20.130 [iCP housekeeper] DEBUG --- SpringBootHikariCP - Pool stats (total=3, active=0, idle=3, waiting=0)
21:09:43.440 [           main] DEBUG --- Finished creating instance of bean 'dslContext'    

Any ideas...?

Answer 1

After taking a thread dump it became clear that the problem is caused by aspectjweaver.

More info can be found here.

By excluding org.jooq in pointcut matching the problem is solved.