Slow execution, initially of buildSessionFactory then subsequent queries, for larger datasets

Hibernate ORM
1

Hello Community, after 20 years of using hibernate, sometimes pushing the envelope, I’m turning to y’all hoping to save some deep diving into the code; we’ve has such success with v 3.x that aside from a few quick looks, there has been no motivation to upgrade til now when we have reworked our build process onto a maven foundation to pull all the 20 some opensource projects we use up to their latest revs

I now have our proprietary framework and several webapps cycling on hibernate 6.6.2 but am running into a perplexing slowdown that is stopping the rollout of our 2 primary systems; the problem first manifests on the buildSessionFactory (Configuration class) call where there is apparently some interrogation of the populated (in our case MySQL) tables since we are seeing execution times jump from 42 seconds for an (almost) empty database to around 7 minutes for the live database for our primary deployment; due to our design reuse, we have other deployments with either the same or nearly the same database schema that are more lightly populated (by a factor of 45) where there is essentially no bump from the empty one; with our second flagship system that has the identical schema with roughly 40% of the population, albeit differently spread across tables, we are seeing around 4 minutes to build the session factory so evidently are suffering some sort of linear performance penalty; I’m obviously not understanding what the factory build is doing, which apparently requires rifling through the table rows

once initialized, we are seeing our overall response times - with the typical mix of explicit queries and subsequent implicit load of traversed references - double or triple from our current deployments with our version 3.x hibernate marshalling; not nearly like the session factory build hit but show stopping nonetheless

we are using ehcache with c3p0 connection pooling so perhaps there is something there; sorry for the detail but wanted to err on the side of providing motivated responders “enough” to factor in; at the risk of TMI, here’s the config properties that we set via direct coding

[2024-12-01 01:43:33] [info]    catalina.base => /var/lib/tomcat9
[2024-12-01 01:43:33] [info]    catalina.home => /usr/share/tomcat9
[2024-12-01 01:43:33] [info]    catalina.useNaming => true
[2024-12-01 01:43:33] [info]    common.loader => "${catalina.base}/lib","${catalina.base}/lib/*.jar","${catalina.home}/lib","${catalina.home}/lib/*.jar"
[2024-12-01 01:43:33] [info]    file.encoding => UTF-8
[2024-12-01 01:43:33] [info]    file.separator => /
[2024-12-01 01:43:33] [info]    hibernate.c3p0.acquire_increment => 5
[2024-12-01 01:43:33] [info]    hibernate.c3p0.contextClassLoaderSource => library
[2024-12-01 01:43:33] [info]    hibernate.c3p0.idle_test_period => 300
[2024-12-01 01:43:33] [info]    hibernate.c3p0.max_size => 50
[2024-12-01 01:43:33] [info]    hibernate.c3p0.max_statement => 0
[2024-12-01 01:43:33] [info]    hibernate.c3p0.min_size => 5
[2024-12-01 01:43:33] [info]    hibernate.c3p0.privilegeSpawnedThreads => true
[2024-12-01 01:43:33] [info]    hibernate.c3p0.timeout => 600
[2024-12-01 01:43:33] [info]    hibernate.cache.ehcache.missing_cache_strategy => create
[2024-12-01 01:43:33] [info]    hibernate.cache.region.factory_class => org.hibernate.cache.ehcache.EhCacheRegionFactory
[2024-12-01 01:43:33] [info]    hibernate.cache.use_query_cache => false
[2024-12-01 01:43:33] [info]    hibernate.cache.use_second_level_cache => true
[2024-12-01 01:43:33] [info]    hibernate.cache.use_structured_entries => true
[2024-12-01 01:43:33] [info]    hibernate.connection.driver_class => com.mysql.cj.jdbc.Driver
[2024-12-01 01:43:33] [info]    hibernate.connection.password => pda321!
[2024-12-01 01:43:33] [info]    hibernate.connection.provider_class => org.hibernate.connection.C3P0ConnectionProvider
[2024-12-01 01:43:33] [info]    hibernate.connection.url => jdbc:mysql://localhost:3306/prom?zeroDateTimeBehavior=convertToNull&serverTimezone=CST6CDT&autoReconnect=true
[2024-12-01 01:43:33] [info]    hibernate.connection.username => prom
[2024-12-01 01:43:33] [info]    hibernate.dialect => com.almega.mavis.services.data.hibernate.MavisMySQLDialect
[2024-12-01 01:43:33] [info]    hibernate.generate_statistics => false
[2024-12-01 01:43:33] [info]    hibernate.globally_quoted_identifiers => true
[2024-12-01 01:43:33] [info]    hibernate.hbm2ddl.auto => update
[2024-12-01 01:43:33] [info]    hibernate.javax.cache.provider => org.hibernate.cache.EHCacheProvider
[2024-12-01 01:43:33] [info]    hibernate.max_fetch_depth => 0
[2024-12-01 01:43:33] [info]    hibernate.show_sql => false
[2024-12-01 01:43:33] [info]    ignore.endorsed.dirs =>
[2024-12-01 01:43:33] [info]    jakarta.persistence.schema-generation.database.action => update
[2024-12-01 01:43:33] [info]    java.class.path => /usr/share/tomcat9/bin/bootstrap.jar:/usr/share/tomcat9/bin/tomcat-juli.jar
[2024-12-01 01:43:33] [info]    java.class.version => 65.0
[2024-12-01 01:43:33] [info]    java.home => /usr/lib/jvm/java-21-openjdk-amd64
[2024-12-01 01:43:33] [info]    java.io.tmpdir => /tmp
[2024-12-01 01:43:33] [info]    java.library.path => /usr/java/packages/lib:/usr/lib/x86_64-linux-gnu/jni:/lib/x86_64-linux-gnu:/usr/lib/x86_64-linux-gnu:/usr/lib/jni:/lib:/usr/lib
[2024-12-01 01:43:33] [info]    java.naming.factory.initial => org.apache.naming.java.javaURLContextFactory
[2024-12-01 01:43:33] [info]    java.naming.factory.url.pkgs => org.apache.naming
[2024-12-01 01:43:33] [info]    java.protocol.handler.pkgs => org.apache.catalina.webresources
[2024-12-01 01:43:33] [info]    java.runtime.name => OpenJDK Runtime Environment
[2024-12-01 01:43:33] [info]    java.runtime.version => 21.0.5+11-Ubuntu-1ubuntu124.04
[2024-12-01 01:43:33] [info]    java.specification.name => Java Platform API Specification
[2024-12-01 01:43:33] [info]    java.specification.vendor => Oracle Corporation
[2024-12-01 01:43:33] [info]    java.specification.version => 21
[2024-12-01 01:43:33] [info]    java.util.logging.config.file => /var/lib/tomcat9/conf/logging.properties
[2024-12-01 01:43:33] [info]    java.util.logging.manager => org.apache.juli.ClassLoaderLogManager
[2024-12-01 01:43:33] [info]    java.vendor => Ubuntu
[2024-12-01 01:43:33] [info]    java.vendor.url => https://ubuntu.com/
[2024-12-01 01:43:33] [info]    java.vendor.url.bug => https://bugs.launchpad.net/ubuntu/+source/openjdk-21
[2024-12-01 01:43:33] [info]    java.version => 21.0.5
[2024-12-01 01:43:33] [info]    java.version.date => 2024-10-15
[2024-12-01 01:43:33] [info]    java.vm.compressedOopsMode => Zero based
[2024-12-01 01:43:33] [info]    java.vm.info => mixed mode, sharing
[2024-12-01 01:43:33] [info]    java.vm.name => OpenJDK 64-Bit Server VM
[2024-12-01 01:43:33] [info]    java.vm.specification.name => Java Virtual Machine Specification
[2024-12-01 01:43:33] [info]    java.vm.specification.vendor => Oracle Corporation
[2024-12-01 01:43:33] [info]    java.vm.specification.version => 21
[2024-12-01 01:43:33] [info]    java.vm.vendor => Ubuntu
[2024-12-01 01:43:33] [info]    java.vm.version => 21.0.5+11-Ubuntu-1ubuntu124.04
[2024-12-01 01:43:33] [info]    jdk.debug => release
[2024-12-01 01:43:33] [info]    jdk.tls.ephemeralDHKeySize => 2048
[2024-12-01 01:43:33] [info]    line.separator =>
[2024-12-01 01:43:33] [info]    MAVIS_HOME => /opt/tomcat/current/webapps/PROM/WEB-INF/rte
[2024-12-01 01:43:33] [info]    native.encoding => UTF-8
[2024-12-01 01:43:33] [info]    org.apache.catalina.security.SecurityListener.UMASK => 0027
[2024-12-01 01:43:33] [info]    os.arch => amd64
[2024-12-01 01:43:33] [info]    os.name => Linux
[2024-12-01 01:43:33] [info]    os.version => 6.8.0-47-generic
[2024-12-01 01:43:33] [info]    package.access => sun.,org.apache.catalina.,org.apache.coyote.,org.apache.jasper.,org.apache.tomcat.
[2024-12-01 01:43:33] [info]    package.definition => sun.,java.,org.apache.catalina.,org.apache.coyote.,org.apache.jasper.,org.apache.naming.,org.apache.tomcat.
[2024-12-01 01:43:33] [info]    path.separator => :
[2024-12-01 01:43:33] [info]    server.loader =>
[2024-12-01 01:43:33] [info]    shared.loader =>
[2024-12-01 01:43:33] [info]    stderr.encoding => UTF-8
[2024-12-01 01:43:33] [info]    stdout.encoding => UTF-8
[2024-12-01 01:43:33] [info]    sun.arch.data.model => 64
[2024-12-01 01:43:33] [info]    sun.boot.library.path => /usr/lib/jvm/java-21-openjdk-amd64/lib
[2024-12-01 01:43:33] [info]    sun.cpu.endian => little
[2024-12-01 01:43:33] [info]    sun.io.unicode.encoding => UnicodeLittle
[2024-12-01 01:43:33] [info]    sun.java.command => org.apache.catalina.startup.Bootstrap start
[2024-12-01 01:43:33] [info]    sun.java.launcher => SUN_STANDARD
[2024-12-01 01:43:33] [info]    sun.jnu.encoding => UTF-8
[2024-12-01 01:43:33] [info]    sun.management.compiler => HotSpot 64-Bit Tiered Compilers
[2024-12-01 01:43:33] [info]    tomcat.util.buf.StringCache.byte.enabled => true
2

Sounds like you’re using Hibernate Schema Tool to either validate or update your existing database schema: you can control this behavior through the hibernate.hbm2ddl.autoconfiguration property, see its javadoc here. To speed up the process, if you don’t require Hibernate to check the schema, you can try setting it to none.

Without seeing specific examples of the entity mappings involved and the queries that are executed it’s basically impossible to help you there. If you believe there are performance problems with some of the operations you are performing, you should try coming up with a detailed test case, ideally a simple runnable project, that clearly show the problem. Keep in mind Hibernate 3 was released nearly 20 years ago, the project has evolved and fundamentally changed since then. Without any additional details, and not knowing your environment, I’m afraid I cannot help you further.

3

Thanks for the feedback Marco, definitely understand that the overall performance hit I’m taking is an open-ended topic without specifics; what I’m hoping is that if I can understand why the simple buildSessionFactory method invocation is row (vs table/column schema) dependent, perhaps that will point to something that guides better the general slowdown; I do have the schema validation controlled so that it only occurs when I, at this point infrequently, change the domain model from whence we automatically generate the mappings; the validation/update seems slower also for v6 vs v3 but that’s not of concern since it seldom is triggered;

I’ve held off with specific mappings, thinking there might be some general lessons learned in the, yes, nearly 20 year evolution to 6 that would indicate whether there is some degradation, however slight, coming in with increased checking, different cache handling, standard adherence, etc that gets multiplied with more table rows; so for the general querying, yep I’ll need to come up with a more focused test configuration (after I double check column indexing and such hasn’t got mucked up with v6 schema auto updating); the buildSessionFactory though, is perplexing with radical construction variation using the same schema/mappings, just loaded differently in the rows

4

Just a follow-up, in case someone else gets drug down the same rabbit hole; turns out that the buildSessionFactory method winds down into schema “migration” (a bit of a surprise) where foreign keys are applied by default after checking if they exist; we are using MySQL with MyISAM storage, which does not support foreign keys and moreover fails silently when they are added; so every server restart the AbstractSchemaMigrator unsuccessfully tries to add them, which for several of our larger tables incurs some significant time (e.g. the systems where I finally localized the problem had one table with 600K+ records taking 40 seconds and our other flagship system has tables with multi-million record counts); so I augmented our MySQLDialect derivative per the below to short-circuit the constraint adding; could possibly have returned false with hasAlterTable which would also block the foreign key checking and addition but didn’t track down whether there would be some other side effect from that, as perhaps with our infrequent schema update

	static final private String EMPTY[] = {};

	private StandardForeignKeyExporter FKEX;

	@Override
	public Exporter<ForeignKey> getForeignKeyExporter() {

		if (FKEX == null)
			FKEX = new StandardForeignKeyExporter(this) {

				@Override
				public String[] getSqlCreateStrings(ForeignKey arg0, Metadata arg1, SqlStringGenerationContext arg2) {
					return EMPTY;
				}

				@Override
				public String[] getSqlDropStrings(ForeignKey foreignKey, Metadata metadata,
						SqlStringGenerationContext context) {
					return EMPTY;
				}

			};
		return FKEX;
	}

will consider this topic closed as I move on to why we are seeing 2+ times slowdown with our queries and secondary fetches; am looking whether there may be some combination of prepared statement caching and connection pooling kicking up

5

You are apparently using hibernate.hbm2ddl.auto with the update action, as I suggested in my previous commit. Just switch this configuration setting to none to avoid running schema migration altogether if you wish to avoid doing it every time you construct a new session factory - schema migration is only supposed to happen as a temporary solution or once in a development environment to then copy the changes, not in a production environment.