Quarkus slow Hibernate startup - Property hard coded on FastBootHibernatePersistenceProvider #16927

leonardowestphal · 2021-04-30T18:33:21Z

quarkus/extensions/hibernate-orm/runtime/src/main/java/io/quarkus/hibernate/orm/runtime/FastBootHibernatePersistenceProvider.java

Line 192 in 9c73b17

    
           runtimeSettingsBuilder.put("hibernate.temp.use_jdbc_metadata_defaults", "true");

When using Quarkus '1.13' on Dev mode the application start up get slow on Hibernate loading metadata (A very large Postgres database. Total start up time: 5 minutes and 30 seconds). The line of code 192 on class FastBootHibernatePersistenceProvider overrides the property 'hibernate.temp.use_jdbc_metadata_defaults' defined on persistence.xml. Is it possible to change this behavior so the application can start fast?

I have two persistence units on persistence.xml. Hibernate initializes both without the metadata, but when Quarkus registers and initializes 'QuarkusStaticDialectFactory' Hibernate uses metadata on org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator (line of code 65) because it is set hard coded on 'FastBootHibernatePersistenceProvider' overriding persistence.xml.

I'm in doubt if it is a bug or it is really necessary for Quarkus.
It seems that Hibernate is initializing the PUs and Quarkus is causing Hibernate to load again due to the use of QuarkusPostgreSQL95Dialect.

quarkus-bot · 2021-04-30T18:33:24Z

/cc @Sanne, @gsmet, @yrodiere

Sanne · 2021-05-01T15:17:57Z

hi @leonardowestphal , no this is an internal property and it's not currently meant for end users to try overriding it.

Could you explain why you think this particularly property is responsible for the slow loading?

Also, could you try and see how fast it loads when you're configuring the application exclusively using the application.properties (and remove the persistence.xml from your project).

Generally speaking, the use of persistence.xml is not optimal: we allow it to simplify migrations from older technologies and for specific advanced cases, but it comes at some drawbacks in how far we can optimise things.

leonardowestphal · 2021-05-03T12:26:57Z

Hi @Sanne , is the same problem related in some Hibernate issues. For example:

And for the reason that I mentioned, Quarkus is loading metadata when registering and initializing QuarkusStaticDialectFactory.

I'm migrating a legacy system that needs to manually define the desired entities, so I need to do this using persistence.xml. Unfortunately in this case I cannot use the 'hibernate.archive.autodetection' property.

Also, from what I noticed, not all properties used by the legacy system can be configured through application.properties

Used properties(I have not yet evaluated which ones I will be able to remove/change):
hibernate.cache.region.factory_class
hibernate.cache.region_prefix
hibernate.cache.use_query_cache
hibernate.cache.use_second_level_cache
hibernate.connection.driver_class
hibernate.dialect
hibernate.discriminator.ignore_explicit_for_joined
hibernate.max_fetch_depth
hibernate.show_sql
hibernate.temp.use_jdbc_metadata_defaults
hibernate.validator.apply_to_ddl
hibernate.validator.autoregister_listeners
hibernate.integration.envers.enabled
javax.persistence.jdbc.url
javax.persistence.jdbc.user
javax.persistence.jdbc.password

One more question. How can I override the password using Quarkus with persistence.xml? So that it's not hard coded on persistence.xml

leonardowestphal · 2021-05-05T12:59:55Z

hi @leonardowestphal , no this is an internal property and it's not currently meant for end users to try overriding it.

Could you explain why you think this particularly property is responsible for the slow loading?

Also, could you try and see how fast it loads when you're configuring the application exclusively using the application.properties (and remove the persistence.xml from your project).

Generally speaking, the use of persistence.xml is not optimal: we allow it to simplify migrations from older technologies and for specific advanced cases, but it comes at some drawbacks in how far we can optimise things.

Can you help me? Why is it not possible to change the value of the 'hibernate.temp.use_jdbc_metadata_defaults' property ?

leonardowestphal · 2021-05-27T19:30:10Z

I resolved it with this PR: #17509

yrodiere · 2021-05-31T07:03:48Z

This is probably a duplicate of #15888

juliaaano · 2021-05-31T07:10:13Z

May also be resolved with #17509

Sanne · 2021-06-09T11:06:46Z

@leonardowestphal could you confirm if you see slow startup even when setting hibernate.hbm2ddl.auto=none ?

(The Quarkus property is https://quarkus.io/guides/hibernate-orm#quarkus-hibernate-orm_quarkus.hibernate-orm.database.generation )

We should be able to bypass the cause of the slowdown when the schema validation is turned off.

sebersole · 2021-06-09T12:52:13Z

As a separate check (do not do in combination with skipping validation), could you also test setting hibernate.temp.use_jdbc_metadata_defaults to false?

This setting controls whether Hibernate will access the JDBC DatabaseMetaData on startup to determine various defaults. Disabling this means you'll need to explicitly configure those settings, but we are curious if this may also contribute to the performance problem you see

Sanne · 2021-06-09T13:10:14Z

one more request: please capture some stacktraces in the slow configuration, hopefully identifying the stack in which we have to wait for multiple minutes.

leonardowestphal · 2021-06-09T13:48:47Z

I will perform these requested tests...

I don't know if this helps, but I noticed that the slowness in my case is due to loading of UDTs: https://www.postgresql.org/docs/9.5/xtypes.html

Using Squirrel SQL client I can disable this type of metadata loading and then everything is faster when using this tool.

leonardowestphal · 2021-06-09T14:00:08Z

As a separate check (do not do in combination with skipping validation), could you also test setting hibernate.temp.use_jdbc_metadata_defaults to false?

This setting controls whether Hibernate will access the JDBC DatabaseMetaData on startup to determine various defaults. Disabling this means you'll need to explicitly configure those settings, but we are curious if this may also contribute to the performance problem you see

This is exactly the point I resolved with this PR: #17509. Using the value false everything is fast!

Sanne · 2021-06-09T14:07:10Z

I noticed that the slowness in my case is due to loading of UDTs:

That's fantastic news, we can easily do something about it.

Sanne · 2021-06-09T15:14:18Z

This should avoid loading all UDT and all keywords, w/o needing to set any property - and without causing problematic side-effects:

HHH-14667 Reduce amount of Database metadata details being loaded during bootstrap hibernate/hibernate-orm#4043

Could you try it @leonardowestphal ?

To build it locally, run ./gradlew publishToMavenLocal from the root, using JDK11.
Then override the version of hibernate-orm with 5.5.1-SNAPSHOT in your projects - careful as Quarkus tends to want to manage its version.

leonardowestphal · 2021-06-09T16:38:11Z

@leonardowestphal could you confirm if you see slow startup even when setting hibernate.hbm2ddl.auto=none ?

(The Quarkus property is https://quarkus.io/guides/hibernate-orm#quarkus-hibernate-orm_quarkus.hibernate-orm.database.generation )

We should be able to bypass the cause of the slowdown when the schema validation is turned off.

None is the default value for Quarkus, however I performed the test using this property in application.properties and it's still slow. (I've already eliminated the use of persistence.xml)

The startup "freezes" a long time in "JDBC driver metadata reported database stores quoted identifiers in neither upper, lower nor mixed case"

Logs (I removed some sensitive data):

2021-06-09 13:21:02,391 DEBUG [io.qua.hib.orm.run.FastBootHibernatePersistenceProvider] (JPA Startup Thread: PU2) Checking persistence-unit [name=PU2, explicit-provider=null] against incoming persistence unit name [PU2]
2021-06-09 13:21:02,391 DEBUG [io.qua.hib.orm.run.FastBootHibernatePersistenceProvider] (JPA Startup Thread: PU2) No PersistenceProvider explicitly requested, assuming Hibernate
2021-06-09 13:21:02,408 FINE  [org.pos.Driver] (agroal-21) Loading driver configuration via classloader jdk.internal.loader.ClassLoaders$AppClassLoader@3d4eac69
2021-06-09 13:21:02,408 FINE  [org.pos.Driver] (agroal-11) Loading driver configuration via classloader jdk.internal.loader.ClassLoaders$AppClassLoader@3d4eac69
2021-06-09 13:21:02,408 FINE  [org.pos.Driver] (agroal-11) Connecting with URL: jdbc:postgresql://<ip>:<port>/<db>
2021-06-09 13:21:02,408 FINE  [org.pos.Driver] (agroal-21) Connecting with URL: jdbc:postgresql://<ip>:<port>/<db>
2021-06-09 13:21:02,411 FINE  [org.pos.jdb.PgConnection] (agroal-11) PostgreSQL JDBC Driver 42.2.20
2021-06-09 13:21:02,411 FINE  [org.pos.jdb.PgConnection] (agroal-21) PostgreSQL JDBC Driver 42.2.20
2021-06-09 13:21:02,412 FINE  [org.pos.jdb.PgConnection] (agroal-21)   setDefaultFetchSize = 0
2021-06-09 13:21:02,412 FINE  [org.pos.jdb.PgConnection] (agroal-11)   setDefaultFetchSize = 0
2021-06-09 13:21:02,413 FINE  [org.pos.jdb.PgConnection] (agroal-21)   setPrepareThreshold = 5
2021-06-09 13:21:02,413 FINE  [org.pos.jdb.PgConnection] (agroal-11)   setPrepareThreshold = 5
2021-06-09 13:21:02,417 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-21) Trying to establish a protocol version 3 connection to <ip>:<port>
2021-06-09 13:21:02,417 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-11) Trying to establish a protocol version 3 connection to <ip>:<port>
2021-06-09 13:21:02,489 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-11) Receive Buffer Size is 65.536
2021-06-09 13:21:02,489 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-21) Receive Buffer Size is 65.536
2021-06-09 13:21:02,489 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-11) Send Buffer Size is 23.040
2021-06-09 13:21:02,489 FINE  [org.pos.cor.v3.ConnectionFactoryImpl] (agroal-21) Send Buffer Size is 23.040
2021-06-09 13:21:02,778 DEBUG [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: PU1) Database ->
       name : PostgreSQL
    version : 12.3
      major : 12
      minor : 3
2021-06-09 13:21:02,778 DEBUG [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: PU2) Database ->
       name : PostgreSQL
    version : 12.3
      major : 12
      minor : 3
2021-06-09 13:21:02,778 DEBUG [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: PU1) Driver ->
       name : PostgreSQL JDBC Driver
    version : 42.2.20
      major : 42
      minor : 2
2021-06-09 13:21:02,778 DEBUG [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: PU2) Driver ->
       name : PostgreSQL JDBC Driver
    version : 42.2.20
      major : 42
      minor : 2
2021-06-09 13:21:02,778 DEBUG [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: PU2) JDBC version : 4.2
2021-06-09 13:21:02,778 DEBUG [org.hib.eng.jdb.env.int.JdbcEnvironmentInitiator] (JPA Startup Thread: PU1) JDBC version : 4.2
2021-06-09 13:21:02,779 DEBUG [org.hib.eng.jdb.env.spi.IdentifierHelperBuilder] (JPA Startup Thread: PU1) JDBC driver metadata reported database stores quoted identifiers in neither upper, lower nor mixed case
2021-06-09 13:21:02,779 DEBUG [org.hib.eng.jdb.env.spi.IdentifierHelperBuilder] (JPA Startup Thread: PU2) JDBC driver metadata reported database stores quoted identifiers in neither upper, lower nor mixed case

sebersole · 2021-06-09T17:36:43Z

@leonardowestphal could you confirm if you see slow startup even when setting hibernate.hbm2ddl.auto=none ?
(The Quarkus property is https://quarkus.io/guides/hibernate-orm#quarkus-hibernate-orm_quarkus.hibernate-orm.database.generation )
We should be able to bypass the cause of the slowdown when the schema validation is turned off.

None is the default value for Quarkus, however I performed the test using this property in application.properties and it's still slow. (I've already eliminated the use of persistence.xml)

I think you nailed it above. If you have a lot of UDT mappings then that part of startup could conceivably take a long time. I had added this for a feature I always wanted to come back and implement, but its not implemented and that method is just an unneeded overhead at the moment. Sanne already implemented some changes to this code I suggested.

Sanne · 2021-06-09T22:16:53Z

@leonardowestphal I've updated my experiment at hibernate/hibernate-orm#4043 . I'm afraid the version I had pushed earlier today was still possibly loading those same objects, this should be better.

I really can't test it as my databases don't show this problem, I hope you could try it.

Also if you can, please share a stacktrace of when it's waiting - that would be much more useful than a log for us to know what exactly is the problem in your case. For example forcing a threaddump while it's waiting.

leonardowestphal · 2021-06-10T03:35:49Z

@leonardowestphal I've updated my experiment at hibernate/hibernate-orm#4043 . I'm afraid the version I had pushed earlier today was still possibly loading those same objects, this should be better.

I really can't test it as my databases don't show this problem, I hope you could try it.

Also if you can, please share a stacktrace of when it's waiting - that would be much more useful than a log for us to know what exactly is the problem in your case. For example forcing a threaddump while it's waiting.

@Sanne

I've tested it with version 5.5.1-SNAPSHOT and the total time has been reduced about 20 seconds, but it's still slow (1+ minute).
Note: I did the test in another database, so the time was shorter than originally mentioned in this issue.
Even so I think it was possible to identify the root cause of the problem at 'org.hibernate.tool.schema.extract.internal.SequenceInformationExtractorLegacyImpl.extractMetadata(SequenceInformationExtractorLegacyImpl.java:42)'

I hope this stacktrace is enough:

"JPA Startup Thread: PU1" #94 prio=5 os_prio=0 cpu=661,35ms elapsed=37,04s tid=0x00007f5364c5c800 nid=0x14b36 runnable  [0x00007f5405988000]
   java.lang.Thread.State: RUNNABLE
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:128)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:113)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:223)
        at org.postgresql.core.PGStream.receive(PGStream.java:602)
        at org.postgresql.core.PGStream.receiveTupleV3(PGStream.java:562)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2252)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:323)
        - locked <0x000000071e602308> (a org.postgresql.core.v3.QueryExecutorImpl)
        at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:481)
        at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:401)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:322)
        at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:308)
        at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:284)
        at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:236)
        at org.hibernate.tool.schema.extract.internal.SequenceInformationExtractorLegacyImpl.extractMetadata(SequenceInformationExtractorLegacyImpl.java:42)
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentImpl.sequenceInformationList(JdbcEnvironmentImpl.java:383)
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentImpl.<init>(JdbcEnvironmentImpl.java:263)
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:114)
        at org.hibernate.engine.jdbc.env.internal.JdbcEnvironmentInitiator.initiateService(JdbcEnvironmentInitiator.java:35)
        at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.initiateService(StandardServiceRegistryImpl.java:101)
        - locked <0x00000007183702f8> (a org.hibernate.boot.registry.internal.StandardServiceRegistryImpl)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.createService(AbstractServiceRegistryImpl.java:263)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:237)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
        - locked <0x00000007183702f8> (a org.hibernate.boot.registry.internal.StandardServiceRegistryImpl)
        at org.hibernate.engine.jdbc.internal.JdbcServicesImpl.configure(JdbcServicesImpl.java:51)
        at org.hibernate.boot.registry.internal.StandardServiceRegistryImpl.configureService(StandardServiceRegistryImpl.java:107)
        - locked <0x00000007183702f8> (a org.hibernate.boot.registry.internal.StandardServiceRegistryImpl)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.initializeService(AbstractServiceRegistryImpl.java:246)
        at org.hibernate.service.internal.AbstractServiceRegistryImpl.getService(AbstractServiceRegistryImpl.java:214)
        - locked <0x00000007183702f8> (a org.hibernate.boot.registry.internal.StandardServiceRegistryImpl)
        at org.hibernate.boot.internal.SessionFactoryOptionsBuilder.<init>(SessionFactoryOptionsBuilder.java:263)
        at io.quarkus.hibernate.orm.runtime.recording.PrevalidatedQuarkusMetadata.buildSessionFactoryOptionsBuilder(PrevalidatedQuarkusMetadata.java:69)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:71)
        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:67)
        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:149)
        - locked <0x000000071e60c428> (a io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:58)
        at java.lang.Thread.run([email protected]/Thread.java:829)

   Locked ownable synchronizers:
        - None

"JPA Startup Thread: PU2" #95 prio=5 os_prio=0 cpu=4702,62ms elapsed=37,04s tid=0x00007f5364c5d000 nid=0x14b37 runnable  [0x00007f5406492000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.reflect.Method.copy([email protected]/Method.java:160)
        at java.lang.reflect.ReflectAccess.copyMethod([email protected]/ReflectAccess.java:144)
        at jdk.internal.reflect.ReflectionFactory.copyMethod([email protected]/ReflectionFactory.java:366)
        at java.lang.Class.copyMethods([email protected]/Class.java:3391)
        at java.lang.Class.getDeclaredMethods([email protected]/Class.java:2309)
        at org.hibernate.internal.util.ReflectHelper.getGetterOrNull(ReflectHelper.java:493)
        at org.hibernate.internal.util.ReflectHelper.findGetterMethod(ReflectHelper.java:452)
        at org.hibernate.internal.util.ReflectHelper.getterMethodOrNull(ReflectHelper.java:599)
        at org.hibernate.property.access.internal.PropertyAccessMixedImpl.getAccessType(PropertyAccessMixedImpl.java:97)
        at org.hibernate.property.access.internal.PropertyAccessMixedImpl.<init>(PropertyAccessMixedImpl.java:47)
        at org.hibernate.property.access.internal.PropertyAccessEnhancedImpl.<init>(PropertyAccessEnhancedImpl.java:28)
        at org.hibernate.property.access.internal.PropertyAccessStrategyEnhancedImpl.buildPropertyAccess(PropertyAccessStrategyEnhancedImpl.java:27)
        at org.hibernate.mapping.Property.getGetter(Property.java:311)
        at org.hibernate.proxy.pojo.ProxyFactoryHelper.validateProxyability(ProxyFactoryHelper.java:88)
        at org.hibernate.tuple.entity.PojoEntityTuplizer.buildProxyFactory(PojoEntityTuplizer.java:100)
        at org.hibernate.tuple.entity.AbstractEntityTuplizer.<init>(AbstractEntityTuplizer.java:160)
        at org.hibernate.tuple.entity.PojoEntityTuplizer.<init>(PojoEntityTuplizer.java:53)
        at jdk.internal.reflect.GeneratedConstructorAccessor118.newInstance(Unknown Source)
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance([email protected]/DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance([email protected]/Constructor.java:490)
        at org.hibernate.tuple.entity.EntityTuplizerFactory.constructTuplizer(EntityTuplizerFactory.java:88)
        at org.hibernate.tuple.entity.EntityTuplizerFactory.constructDefaultTuplizer(EntityTuplizerFactory.java:116)
        at org.hibernate.tuple.entity.EntityMetamodel.<init>(EntityMetamodel.java:432)
        at org.hibernate.persister.entity.AbstractEntityPersister.<init>(AbstractEntityPersister.java:612)
        at org.hibernate.persister.entity.SingleTableEntityPersister.<init>(SingleTableEntityPersister.java:126)
        at jdk.internal.reflect.GeneratedConstructorAccessor119.newInstance(Unknown Source)
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance([email protected]/DelegatingConstructorAccessorImpl.java:45)
        at java.lang.reflect.Constructor.newInstance([email protected]/Constructor.java:490)
        at org.hibernate.persister.internal.PersisterFactoryImpl.createEntityPersister(PersisterFactoryImpl.java:96)
        at org.hibernate.persister.internal.PersisterFactoryImpl.createEntityPersister(PersisterFactoryImpl.java:77)
        at org.hibernate.metamodel.internal.MetamodelImpl.initialize(MetamodelImpl.java:181)
        at org.hibernate.internal.SessionFactoryImpl.<init>(SessionFactoryImpl.java:312)
        at io.quarkus.hibernate.orm.runtime.boot.FastBootEntityManagerFactoryBuilder.build(FastBootEntityManagerFactoryBuilder.java:73)
        at io.quarkus.hibernate.orm.runtime.FastBootHibernatePersistenceProvider.createEntityManagerFactory(FastBootHibernatePersistenceProvider.java:67)
        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:80)
        at javax.persistence.Persistence.createEntityManagerFactory(Persistence.java:55)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit.get(JPAConfig.java:149)
        - locked <0x000000072066e468> (a io.quarkus.hibernate.orm.runtime.JPAConfig$LazyPersistenceUnit)
        at io.quarkus.hibernate.orm.runtime.JPAConfig$1.run(JPAConfig.java:58)
        at java.lang.Thread.run([email protected]/Thread.java:829)

   Locked ownable synchronizers:
        - None

Sanne · 2021-06-10T07:21:57Z

Very interesting, thanks!

So it's sequence details; it gets a bit more complicated but let's see what we can do.

Can you give us an idea of how many sequences you have in the database, and show how a typical entity is mapped to use them?

leonardowestphal · 2021-06-10T12:59:10Z

Very interesting, thanks!

So it's sequence details; it gets a bit more complicated but let's see what we can do.

Can you give us an idea of how many sequences you have in the database, and show how a typical entity is mapped to use them?

There are about 100,000. It's a little scary, but this high number is due to a legacy solution.

An example:

@Entity
@Table(name = "example", schema = "zxc")
@DynamicUpdate
public class Example {
	
	@SequenceGenerator(name = "tb_seq_name", sequenceName = "zxc.tb_seq_name")
	@GeneratedValue(generator = "tb_seq_name")
	@Id
	@Column(name = "col_name", unique = true, nullable = false)
	private Long id;

leonardowestphal · 2021-06-10T13:14:55Z

Would it be feasible to create a specific property to allow not loading the metadata of the sequences? Or maybe something similar... to be less comprehensive than property 'hibernate.temp.use_jdbc_metadata_defaults' and decrease the risks involved.

Sanne · 2021-06-10T13:43:15Z

Yes we can introduce that; I'll look into it. Thanks for all details!

leonardowestphal · 2021-06-10T13:51:42Z

Yes we can introduce that; I'll look into it. Thanks for all details!

Thanks @Sanne

Sanne · 2021-06-10T16:55:27Z

@leonardowestphal I have another draft for you and hope you could test it :)

you'll have to set the Hibernate configuration property hibernate.id.sequence.increment_size_mismatch_strategy to NONE (and yes Quarkus doesn't expose this but I trust you can workaround it)

HHH-14667 Reduce amount of Database metadata details being loaded during bootstrap hibernate/hibernate-orm#4043

If this works, I'll cleanup the code and merge it in ORM, then patch Quarkus to always set this flag.

leonardowestphal · 2021-06-10T18:52:02Z

@leonardowestphal I have another draft for you and hope you could test it :)

you'll have to set the Hibernate configuration property hibernate.id.sequence.increment_size_mismatch_strategy to NONE (and yes Quarkus doesn't expose this but I trust you can workaround it)

hibernate/hibernate-orm#4043

If this works, I'll cleanup the code and merge it in ORM, then patch Quarkus to always set this flag.

@Sanne
It worked successfully!!! Great!!!
So are you going to set it to a fixed value 'none' in Quarkus? Could you backport it to version 1.13.x?
I don't really understand how this property works, could you explain?

Thank you!

Sanne · 2021-06-10T19:30:38Z

nice, thanks to you for all the quick testing and details :)

So, we did a couple of things.

The increment_size_mismatch_strategy property gives users a choice regarding what to do when the sequence increment sizes as defined in the DB don't match the increment_size parameter on a pooled optimizer - as that can lead to problems. The options (until today) were: either we log the problem as a warning, or we throw an exception, or we override the mapping with the value found in the DB for the matching sequence. I've added now an option none which gives the option to skip this validation altogether.

In another area of the code, during bootstrap when loading the ExtractedDatabaseMetaData (which is what you would skip altogether when setting the use_jdbc_metadata_defaults property), among other things it was loading all sequence information - as you've noticed in your stacktrace. I've removed this loading, and made it lazily triggered: these details of sequences were only used by the validation of increment sizes I've mentioned above. So - if you disable validation, the loading of sequences gets skipped altogether as a side-effect. But it's better: these sequences are also skipped altogether if you don't use any sequence, or if the sequence optimisers you use aren't "pooled" which means they don't need to know what the increment size is. (So this patch will help also many other users who don't know or care about the increment_size_mismatch_strategy property but just don't happen to have such optimizers enabled).

Furthermore, I've noticed that these checks are redundant if you have schema validation enabled: the schema validator will also check for the same mistakes and throw an exception. I do assume and recommend people that deploy in production / staging to use the schema validation - or if they don't to take good care that the code is matching the schema expectations - so that kinda makes this flag redundant and that's why I believe it should be disabled in Quarkus: you'll still have this validated when you enable schema validation - and when you don't enable schema validation, we will trust you on that choice.

In short, this disables loading of the sequence metadata but it doesn't fully disable the other things we need from ExtractedDatabaseMetaData - some of those details are very important to enable further optimisations, and sometimes even workarounds for specific driver issues, or database issues which only manifest on certain versions. so you get to disable the slow ones w/o throwing out the baby with the bathwater - and without adding more configuration propeties so I'm happy ;-)

And sure we'll start the backporting process; I'm not really sure which release train this will be able to catch - so can't promise it being included in the very next maintenance release, but it shouldn't take too long.

famod · 2021-06-10T19:37:01Z

I've been watching this from the sidelines and I just wanted to say thank you @Sanne for explaining things so thoroughly (and it was not the first time you took the time to do so). Really appreciated!

leonardowestphal · 2021-06-10T19:45:03Z

nice, thanks to you for all the quick testing and details :)

So, we did a couple of things.

The increment_size_mismatch_strategy property gives users a choice regarding what to do when the sequence increment sizes as defined in the DB don't match the increment_size parameter on a pooled optimizer - as that can lead to problems. The options (until today) were: either we log the problem as a warning, or we throw an exception, or we override the mapping with the value found in the DB for the matching sequence. I've added now an option none which gives the option to skip this validation altogether.

In another area of the code, during bootstrap when loading the ExtractedDatabaseMetaData (which is what you would skip altogether when setting the use_jdbc_metadata_defaults property), among other things it was loading all sequence information - as you've noticed in your stacktrace. I've removed this loading, and made it lazily triggered: these details of sequences were only used by the validation of increment sizes I've mentioned above. So - if you disable validation, the loading of sequences gets skipped altogether as a side-effect. But it's better: these sequences are also skipped altogether if you don't use any sequence, or if the sequence optimisers you use aren't "pooled" which means they don't need to know what the increment size is. (So this patch will help also many other users who don't know or care about the increment_size_mismatch_strategy property but just don't happen to have such optimizers enabled).

Furthermore, I've noticed that these checks are redundant if you have schema validation enabled: the schema validator will also check for the same mistakes and throw an exception. I do assume and recommend people that deploy in production / staging to use the schema validation - or if they don't to take good care that the code is matching the schema expectations - so that kinda makes this flag redundant and that's why I believe it should be disabled in Quarkus: you'll still have this validated when you enable schema validation - and when you don't enable schema validation, we will trust you on that choice.

In short, this disables loading of the sequence metadata but it doesn't fully disable the other things we need from ExtractedDatabaseMetaData - some of those details are very important to enable further optimisations, and sometimes even workarounds for specific driver issues, or database issues which only manifest on certain versions. so you get to disable the slow ones w/o throwing out the baby with the bathwater - and without adding more configuration propeties so I'm happy ;-)

And sure we'll start the backporting process; I'm not really sure which release train this will be able to catch - so can't promise it being included in the very next maintenance release, but it shouldn't take too long.

I'm immensely grateful for all the answers and the great help you have given me.

Now we can proceed with our project with the certainty that these issues have been overcome. Thanks again for all your support.

Sanne · 2021-06-10T19:53:48Z

My pleasure :) and many thanks also to @sebersole , @yrodiere and @dreab8 who helped with it too.

leonardowestphal · 2021-06-10T19:56:06Z

My pleasure :) and many thanks also to @sebersole , @yrodiere and @dreab8 who helped with it too.

Thank you guys!

quarkus-bot bot added area/hibernate-orm Hibernate ORM area/persistence OBSOLETE, DO NOT USE labels Apr 30, 2021

famod mentioned this issue May 27, 2021

Allows to define the loading of jdbc metadata on the .properties or persistence.xml #17509

Closed

This was referenced Jun 14, 2021

Upgrade to Hibernate ORM 5.5.2.Final #17894

Merged

hibernate.temp.use_jdbc_metadata_defaults=false setting is ignored in persistence.xml #15888

Closed

Sanne closed this as completed in #17894 Jun 14, 2021

quarkus-bot bot added this to the 2.1 - main milestone Jun 14, 2021

gsmet modified the milestones: 2.1 - main, 2.0.0.Final Jun 21, 2021

Sanne mentioned this issue Jun 22, 2021

Make hibernate.temp.use_jdbc_metadata_defaults configurable from persistence.xml #15954

Closed

jonenst mentioned this issue Nov 10, 2023

HHH-17082 - Improve documentation of configuration settings hibernate/hibernate-orm#7182

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Quarkus slow Hibernate startup - Property hard coded on FastBootHibernatePersistenceProvider #16927

Quarkus slow Hibernate startup - Property hard coded on FastBootHibernatePersistenceProvider #16927

leonardowestphal commented Apr 30, 2021

quarkus-bot bot commented Apr 30, 2021

Sanne commented May 1, 2021

leonardowestphal commented May 3, 2021

leonardowestphal commented May 5, 2021

leonardowestphal commented May 27, 2021

yrodiere commented May 31, 2021

juliaaano commented May 31, 2021

Sanne commented Jun 9, 2021 •

edited

Loading

sebersole commented Jun 9, 2021

Sanne commented Jun 9, 2021

leonardowestphal commented Jun 9, 2021

leonardowestphal commented Jun 9, 2021

Sanne commented Jun 9, 2021

Sanne commented Jun 9, 2021

leonardowestphal commented Jun 9, 2021 •

edited

Loading

sebersole commented Jun 9, 2021

Sanne commented Jun 9, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021 •

edited

Loading

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021 •

edited

Loading

Sanne commented Jun 10, 2021

famod commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

Quarkus slow Hibernate startup - Property hard coded on FastBootHibernatePersistenceProvider #16927

Quarkus slow Hibernate startup - Property hard coded on FastBootHibernatePersistenceProvider #16927

Comments

leonardowestphal commented Apr 30, 2021

quarkus-bot bot commented Apr 30, 2021

Sanne commented May 1, 2021

leonardowestphal commented May 3, 2021

leonardowestphal commented May 5, 2021

leonardowestphal commented May 27, 2021

yrodiere commented May 31, 2021

juliaaano commented May 31, 2021

Sanne commented Jun 9, 2021 • edited Loading

sebersole commented Jun 9, 2021

Sanne commented Jun 9, 2021

leonardowestphal commented Jun 9, 2021

leonardowestphal commented Jun 9, 2021

Sanne commented Jun 9, 2021

Sanne commented Jun 9, 2021

leonardowestphal commented Jun 9, 2021 • edited Loading

sebersole commented Jun 9, 2021

Sanne commented Jun 9, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021 • edited Loading

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021 • edited Loading

Sanne commented Jun 10, 2021

famod commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 10, 2021

leonardowestphal commented Jun 10, 2021

Sanne commented Jun 9, 2021 •

edited

Loading

leonardowestphal commented Jun 9, 2021 •

edited

Loading

leonardowestphal commented Jun 10, 2021 •

edited

Loading

leonardowestphal commented Jun 10, 2021 •

edited

Loading