HHH-15854 Performance tests demonstrating regressions in Hibernate 6 (Main)

hibernate-core/src/test/java/org/hibernate/orm/test/query/criteria/CriteriaPerformanceTest.java

@@ -0,0 +1,177 @@
+package org.hibernate.orm.test.query.criteria;
+
+import java.text.MessageFormat;
+import java.time.Duration;
+import java.time.Instant;
+import java.util.ArrayList;
+import java.util.List;
+
+import org.hibernate.cfg.AvailableSettings;
+
+import org.hibernate.testing.orm.junit.DialectFeatureChecks;
+import org.hibernate.testing.orm.junit.EntityManagerFactoryScope;
+import org.hibernate.testing.orm.junit.Jpa;
+import org.hibernate.testing.orm.junit.RequiresDialectFeature;
+import org.hibernate.testing.orm.junit.Setting;
+import org.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.Test;
+
+import jakarta.persistence.CascadeType;
+import jakarta.persistence.Column;
+import jakarta.persistence.Entity;
+import jakarta.persistence.EntityManager;
+import jakarta.persistence.FetchType;
+import jakarta.persistence.FlushModeType;
+import jakarta.persistence.GeneratedValue;
+import jakarta.persistence.GenerationType;
+import jakarta.persistence.Id;
+import jakarta.persistence.JoinColumn;
+import jakarta.persistence.ManyToOne;
+import jakarta.persistence.OneToMany;
+import jakarta.persistence.OneToOne;
+import jakarta.persistence.Table;
+
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertNotNull;
+
+//@Disabled("Manual performance test")
+@Jpa(
+		annotatedClasses = {
+				CriteriaPerformanceTest.Author.class,
+				CriteriaPerformanceTest.AuthorDetails.class,
+				CriteriaPerformanceTest.Book.class
+		},
+		integrationSettings = {
+				@Setting(name = AvailableSettings.DEFAULT_BATCH_FETCH_SIZE, value = "10")
+		}
+)
+@RequiresDialectFeature(feature = DialectFeatureChecks.SupportsIdentityColumns.class)
+public class CriteriaPerformanceTest {
+
+	@Test
+	public void testFetchEntityWithAssociationsPerformance(EntityManagerFactoryScope scope) {
+		scope.inTransaction( entityManager -> {
+			for ( int i = 0; i < 1000; i++ ) {
+				populateData( entityManager );
+			}
+		} );
+		scope.inTransaction( entityManager -> {
+			entityManager.setFlushMode( FlushModeType.COMMIT );
+
+			final Instant startTime = Instant.now();
+
+			for ( int i = 0; i < 100_000; i++ ) {
+				final List<Author> authors = entityManager.createQuery( "from Author", Author.class ).getResultList();
+				assertNotNull( authors );
+				authors.forEach( author -> assertFalse( author.books.isEmpty() ) );
+			}
+
+			System.out.println( MessageFormat.format(
+					"{0} took {1}",
+					"Query",
+					Duration.between( startTime, Instant.now() )
+			) );
+		} );
+	}
+
+	@Test
+	public void testFetchEntityWithAssociationsPerformanceSmallTransactions(EntityManagerFactoryScope scope) {
+		scope.inTransaction( entityManager -> {
+			for ( int i = 0; i < 1000; i++ ) {
+				populateData( entityManager );
+			}
+		} );
+
+		final Instant startTime = Instant.now();
+
+		for ( int i = 0; i < 1_000; i++ ) {
+			scope.inTransaction( entityManager -> {
+				final List<Author> authors = entityManager.createQuery( "from Author", Author.class )
+						.getResultList();
+				assertNotNull( authors );
+				authors.forEach( author -> assertFalse( author.books.isEmpty() ) );
+			} );
+		}
+
+		System.out.println( MessageFormat.format(
+				"{0} took {1}",
+				"Query",
+				Duration.between( startTime, Instant.now() )
+		) );
+	}
+
+	@AfterEach
+	public void cleanUpTestData(EntityManagerFactoryScope scope) {
+		scope.inTransaction( (session) -> {
+			session.createQuery( "delete Book" ).executeUpdate();
+			session.createQuery( "delete Author" ).executeUpdate();
+			session.createQuery( "delete AuthorDetails" ).executeUpdate();
+		} );
+	}
+
+	public void populateData(EntityManager entityManager) {
+		final Book book = new Book();
+		book.name = "HTTP Definitive guide";
+
+		final Author author = new Author();
+		author.name = "David Gourley";
+
+		final AuthorDetails details = new AuthorDetails();
+		details.name = "Author Details";
+		details.author = author;
+		author.details = details;
+
+		author.books.add( book );
+		book.author = author;
+
+		entityManager.persist( author );
+		entityManager.persist( book );
+	}
+
+	@Entity(name = "Author")
+	@Table(name = "Author")
+	public static class Author {
+		@Id
+		@GeneratedValue(strategy = GenerationType.IDENTITY)
+		public Long authorId;
+
+		@Column
+		public String name;
+
+		@OneToMany(fetch = FetchType.LAZY, mappedBy = "author")
+		public List<Book> books = new ArrayList<>();
+
+		@OneToOne(fetch = FetchType.EAGER, optional = false, cascade = CascadeType.ALL, orphanRemoval = true)
+		public AuthorDetails details;
+
+	}
+
+	@Entity(name = "AuthorDetails")
+	@Table(name = "AuthorDetails")
+	public static class AuthorDetails {
+		@Id
+		@GeneratedValue(strategy = GenerationType.IDENTITY)
+		public Long detailsId;
+
+		@Column
+		public String name;
+
+		@OneToOne(fetch = FetchType.LAZY, mappedBy = "details", optional = false)
+		public Author author;
+	}
+
+	@Entity(name = "Book")
+	@Table(name = "Book")
+	public static class Book {
+		@Id
+		@GeneratedValue(strategy = GenerationType.IDENTITY)
+		public Long bookId;
+
+		@Column
+		public String name;
+
+		@ManyToOne(fetch = FetchType.LAZY, optional = false)
+		@JoinColumn(name = "author_id", nullable = false)
+		public Author author;
+	}
+}

hibernate-core/src/test/resources/hibernate.properties

@@ -16,7 +16,7 @@ hibernate.connection.autocommit false
 hibernate.connection.initial_pool_size 0
 hibernate.connection.pool_size 5
 
-hibernate.show_sql true
+hibernate.show_sql false
 hibernate.format_sql true
 hibernate.highlight_sql true
 

hibernate-core/src/test/resources/log4j2.properties

@@ -30,30 +30,26 @@ logger.subsystem-root.level=info
 logger.subsystem-root.additivity=false
 logger.subsystem-root.appenderRef.subsystem.ref=subsystem
 
-logger.jdbc-batch.name=org.hibernate.orm.jdbc.batch
-logger.jdbc-batch.level=trace
-
 logger.jdbc-bind.name=org.hibernate.orm.jdbc.bind
-logger.jdbc-bind.level=trace
-
+logger.jdbc-bind.level=info
 logger.jdbc-extract.name=org.hibernate.orm.jdbc.extract
-logger.jdbc-extract.level=trace
+logger.jdbc-extract.level=info
 
 # "Graph Language" Antlr parsing
 logger.graph.name=org.hibernate.orm.graph
-#logger.graph.level=debug
+#logger.graph.level=info
 
 # Logging related to the creation of DomainResult/Fetch graphs
 logger.sql-result-graph.name=org.hibernate.orm.sql.results
-#logger.sql-result-graph.level=debug
+#logger.sql-result-graph.level=info
 
 # Logs generated DomainResult/Fetch AST graph
 logger.sql-result-ast.name=org.hibernate.orm.sql.results.graph.AST
-#logger.sql-result-ast.level=debug
+#logger.sql-result-ast.level=info
 
 ## Logs every SQM tree
 logger.sqm-tree.name=org.hibernate.orm.query.sqm.ast
-#logger.sqm-tree.level=debug
+#logger.sqm-tree.level=info
 
 
 
@@ -70,42 +66,36 @@ logger.tests.additivity=false
 logger.tests.appenderRef.stdout.ref=stdout
 
 logger.hbm2ddl.name=org.hibernate.tool.hbm2ddl
-#logger.hbm2ddl.level=trace
+#logger.hbm2ddl.level=info
 
 logger.testing-cache.name=org.hibernate.testing.cache
-#logger.testing-cache.level=debug
-
+#logger.testing-cache.level=info
 logger.hql-internal-ast.name=org.hibernate.hql.internal.ast
-logger.hql-internal-ast.level=debug
-
+logger.hql-internal-ast.level=info
 logger.sql-ordering-antlr.name=org.hibernate.sql.ordering.antlr
-logger.sql-ordering-antlr.level=debug
-
+logger.sql-ordering-antlr.level=info
 logger.load-plan-impl.name=org.hibernate.loader.plan2.build.internal.LoadPlanImpl
-logger.load-plan-impl.level=debug
+logger.load-plan-impl.level=info
 logger.load-plan-tree-printer.name=org.hibernate.loader.plan2.build.spi.LoadPlanTreePrinter
-logger.load-plan-tree-printer.level=debug
+logger.load-plan-tree-printer.level=info
 logger.entity-load-query-details.name=org.hibernate.loader.plan2.exec.spi.EntityLoadQueryDetails
-logger.entity-load-query-details.level=debug
-
+logger.entity-load-query-details.level=info
 logger.statistical-logging-session-event-listener.name=org.hibernate.engine.internal.StatisticalLoggingSessionEventListener
-logger.statistical-logging-session-event-listener.level=info
-
+logger.statistical-logging-session-event-listener.level=warn
 logger.model-binder.name=org.hibernate.boot.model.source.internal.hbm.ModelBinder
-logger.model-binder.level=debug
+logger.model-binder.level=info
 logger.java-type-descriptor-registry.name=org.hibernate.type.descriptor.java.JavaTypeRegistry
-logger.java-type-descriptor-registry.level=debug
-
+logger.java-type-descriptor-registry.level=info
 logger.bytecode-enhancement.name=org.hibernate.bytecode.enhance
-logger.bytecode-enhancement.level=debug
+logger.bytecode-enhancement.level=info
 
 logger.results-loading-entity.name=org.hibernate.orm.results.loading.entity
 #logger.results-loading-entity.level=debug
 
 logger.entity-action.name=org.hibernate.action.internal.EntityAction
-#logger.entity-action.level=debug
+#logger.entity-action.level=info
 logger.cascade.name=org.hibernate.engine.internal.Cascade
-#logger.cascade.level=trace
+#logger.cascade.level=info
 
 logger.global-temp-strategy.name=org.hibernate.query.sqm.mutation.internal.temptable.GlobalTemporaryTableStrategy
 logger.global-temp-strategy.level=trace
@@ -114,17 +104,15 @@ logger.merged-entity-copies.name=org.hibernate.event.internal.EntityCopyAllowedL
 ### When entity copy merge functionality is enabled using:
 ### hibernate.event.merge.entity_copy_observer=log, the following will
 ### provide information about merged entity copies.
-#logger.merged-entity-copies.level=debug
-
+#logger.merged-entity-copies.level=info
 logger.scanning-coordinator.name=org.hibernate.boot.model.process.internal.ScanningCoordinator
-logger.scanning-coordinator.level=debug
+logger.scanning-coordinator.level=info
 logger.abstract-persistent-collection.name=org.hibernate.collection.spi.AbstractPersistentCollection
-logger.abstract-persistent-collection.level=debug
-
+logger.abstract-persistent-collection.level=info
 logger.cache.name=org.hibernate.cache
-logger.cache.level=trace
+logger.cache.level=info
 logger.stat.name=org.hibernate.stat
-logger.stat.level=trace
+logger.stat.level=info
 
 ###############################################################################
 ## Log a list of functions registered by the Dialect
@@ -138,7 +126,7 @@ org.hibernate.HQL_FUNCTIONS=info
 logger.junit.name=org.hibernate.testing.orm.junit
 logger.junit.additivity=false
 logger.junit.appenderRef.subsystem.ref=subsystem
-#logger.junit.level=debug
+#logger.junit.level=info
 
 
 ###############################################################################