System property stops taking effect when moved to application.properties

Question

I have a Spring Boot application that uses Spring Data and Hibernate for data access. I initially encountered significantly long application start-up times. So, based on this answer, I set 'hibernate.temp.use_jdbc_metadata_defaults' to 'false' as a system property (-D). The application startup time issue was resolved.

Now, I moved that configuration from a system property to application.properties. The delayed application start-up issue has returned.

My application.properties:

hibernate.temp.use_jdbc_metadata_defaults=false
spring.jpa.database-platform=org.hibernate.dialect.PostgreSQLDialect
spring.jpa.show-sql=true
spring.jpa.hibernate.ddl-auto=none
spring.datasource.validation-query=SELECT 1
spring.datasource.testOnBorrow=true
spring.datasource.testWhileIdle=true

After setting "org.springframework.core.env" to "DEBUG" logging, I see that the property is resolved from application.properties (as expected).

INFO   | jvm 1    | 2015/07/20 19:47:15 | 19:47:15.211 [WrapperJarAppMain] DEBUG o.s.c.e.PropertySourcesPropertyResolver - Found key 'spring.jpa.database-platform' in [applicationConfig: [classpath:/application.properties]] with type [String] and value 'org.hibernate.dialect.PostgreSQLDialect'
...
INFO   | jvm 1    | 2015/07/20 19:47:15 | 19:47:15.226 [WrapperJarAppMain] DEBUG o.s.c.e.PropertySourcesPropertyResolver - Found key 'hibernate.temp.use_jdbc_metadata_defaults' in [applicationConfig: [classpath:/application.properties]] with type [String] and value 'false'
...
INFO   | jvm 1    | 2015/07/20 19:47:15 | 19:47:15.229 [WrapperJarAppMain] DEBUG o.s.c.e.PropertySourcesPropertyResolver - Found key 'spring.jpa.hibernate.ddl-auto' in [applicationConfig: [classpath:/application.properties]] with type [String] and value 'none'

During the delayed startup, the app stalls at a particular point and then resumes. When it is stalled, "jstack"ing the JVM gives the following result:

INFO   | jvm 1    | 2015/07/20 19:47:58 | "WrapperJarAppMain" #20 prio=5 os_prio=0 tid=0x00007fb1ec02b800 nid=0x1d39 runnable [0x00007fb248257000]
INFO   | jvm 1    | 2015/07/20 19:47:58 |    java.lang.Thread.State: RUNNABLE
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at java.net.SocketInputStream.socketRead0(Native Method)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at java.net.SocketInputStream.read(SocketInputStream.java:170)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at java.net.SocketInputStream.read(SocketInputStream.java:141)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:143)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:112)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:71)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:282)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1803)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:255)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       - locked <0x000000077a9f8ca0> (a org.postgresql.core.v3.QueryExecutorImpl)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:570)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:420)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.jdbc2.TypeInfoCache.getPGType(TypeInfoCache.java:323)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       - locked <0x000000077aa00ce0> (a org.postgresql.jdbc2.TypeInfoCache)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.jdbc2.TypeInfoCache.getSQLType(TypeInfoCache.java:175)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.jdbc2.TypeInfoCache.requiresQuoting(TypeInfoCache.java:711)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.postgresql.jdbc2.AbstractJdbc2DatabaseMetaData.getTypeInfo(AbstractJdbc2DatabaseMetaData.java:4002)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.engine.jdbc.spi.TypeInfo.extractTypeInfo(TypeInfo.java:101)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.engine.jdbc.internal.JdbcServicesImpl.configure(JdbcServicesImpl.java:163)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:111)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:234)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:206)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.cfg.Configuration.buildTypeRegistrations(Configuration.java:1887)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1845)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$4.perform(EntityManagerFactoryBuilderImpl.java:852)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl$4.perform(EntityManagerFactoryBuilderImpl.java:845)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.boot.registry.classloading.internal.ClassLoaderServiceImpl.withTccl(ClassLoaderServiceImpl.java:398)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.hibernate.jpa.boot.internal.EntityManagerFactoryBuilderImpl.build(EntityManagerFactoryBuilderImpl.java:844)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.orm.jpa.vendor.SpringHibernateJpaPersistenceProvider.createContainerEntityManagerFactory(SpringHibernateJpaPersistenceProvider.java:60)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:343)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:318)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1633)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1570)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:539)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:476)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:303)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       - locked <0x00000006dc2676d0> (a java.util.concurrent.ConcurrentHashMap)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:299)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.context.support.AbstractApplicationContext.getBean(AbstractApplicationContext.java:956)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:747)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:480)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       - locked <0x00000006dbd48650> (a java.lang.Object)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:118)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:686)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.boot.SpringApplication.run(SpringApplication.java:320)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.boot.SpringApplication.run(SpringApplication.java:957)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.boot.SpringApplication.run(SpringApplication.java:946)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at xyz.abc.AppApplication.main(AppApplication.java:10)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at java.lang.reflect.Method.invoke(Method.java:497)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:53)
INFO   | jvm 1    | 2015/07/20 19:47:58 |       at java.lang.Thread.run(Thread.java:745)
INFO   | jvm 1    | 2015/07/20 19:47:58 |

From "org.postgresql.jdbc2.TypeInfoCache.getSQLType" (in the above stack), I think Hibernate is still attempting to load metadata. This runs contrary to my configuration.

I would appreciate any pointers on how moving a configuration from a system property to application.properties can cause it to not take effect?

Answer 1

To specify any property that isn't in the default spring.jpa expected properties use spring.jpa.properties.<your-property-name-here>.

So instead of

hibernate.temp.use_jdbc_metadata_defaults=false

Use this instead in your application.properties.

spring.jpa.properties.hibernate.temp.use_jdbc_metadata_defaults=false

This is explained in this section of the Spring Boot reference guide.