HHH-18907 improve how statistics are logged

hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java

@@ -51,11 +51,6 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "Already session bound on call to bind(); make sure you clean up your sessions", id = 2)
 	void alreadySessionBound();
 
-	@LogMessage(level = WARN)
-	@Message(value = "JTASessionContext being used with JDBC transactions; auto-flush will not operate correctly with getCurrentSession()",
-			id = 8)
-	void autoFlushWillNotWork();
-
 	@LogMessage(level = WARN)
 	@Message(value = "Configuration settings with for connection provider '%s' are set, but the connection provider is not on the classpath; these properties will be ignored",
 			id = 22)
@@ -81,26 +76,6 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "Closing", id = 31)
 	void closing();
 
-	@LogMessage(level = INFO)
-	@Message(value = "Collections fetched (minimize this): %s", id = 32)
-	void collectionsFetched(long collectionFetchCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Collections loaded: %s", id = 33)
-	void collectionsLoaded(long collectionLoadCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Collections recreated: %s", id = 34)
-	void collectionsRecreated(long collectionRecreateCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Collections removed: %s", id = 35)
-	void collectionsRemoved(long collectionRemoveCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Collections updated: %s", id = 36)
-	void collectionsUpdated(long collectionUpdateCount);
-
 	@LogMessage(level = WARN)
 	@Message(value = "Composite-id class does not override equals(): %s", id = 38)
 	void compositeIdClassDoesNotOverrideEquals(String name);
@@ -109,10 +84,6 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "Composite-id class does not override hashCode(): %s", id = 39)
 	void compositeIdClassDoesNotOverrideHashCode(String name);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Connections obtained: %s", id = 48)
-	void connectionsObtained(long connectCount);
-
 	@LogMessage(level = WARN)
 	@Message(value = "Ignoring bag join fetch [%s] due to prior collection join fetch", id = 51)
 	void containsJoinFetchedCollection(String role);
@@ -137,26 +108,6 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "Found more than one <persistence-unit-metadata>, subsequent ignored", id = 74)
 	void duplicateMetadata();
 
-	@LogMessage(level = INFO)
-	@Message(value = "Entities deleted: %s", id = 76)
-	void entitiesDeleted(long entityDeleteCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Entities fetched (minimize this): %s", id = 77)
-	void entitiesFetched(long entityFetchCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Entities inserted: %s", id = 78)
-	void entitiesInserted(long entityInsertCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Entities loaded: %s", id = 79)
-	void entitiesLoaded(long entityLoadCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Entities updated: %s", id = 80)
-	void entitiesUpdated(long entityUpdateCount);
-
 	@LogMessage(level = WARN)
 	@Message(value = "Entity [%s] is abstract-class/interface explicitly mapped as non-abstract; be sure to supply entity-names",
 			id = 84)
@@ -184,10 +135,6 @@ public interface CoreMessageLogger extends BasicLogger {
 			+ " to unsafe use of the session): %s", id = 99)
 	void failed(Throwable throwable);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Flushes: %s", id = 105)
-	void flushes(long flushCount);
-
 	@LogMessage(level = INFO)
 	@Message(value = "Forcing table use for sequence-style generator due to pooled optimizer selection where db does not support pooled sequences",
 			id = 107)
@@ -246,14 +193,6 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "Lazy property fetching available for: %s", id = 157)
 	void lazyPropertyFetchingAvailable(String name);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Logging statistics....", id = 161)
-	void loggingStatistics();
-
-	@LogMessage(level = INFO)
-	@Message(value = "Max query time: %sms", id = 173)
-	void maxQueryTime(long queryExecutionMaxTime);
-
 	@LogMessage(level = WARN)
 	@Message(value = "Function template anticipated %s arguments, but %s arguments encountered", id = 174)
 	void missingArguments(
@@ -274,10 +213,6 @@ public interface CoreMessageLogger extends BasicLogger {
 			id = 182)
 	void noDefaultConstructor(String name);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Optimistic lock failures: %s", id = 187)
-	void optimisticLockFailures(long optimisticFailureCount);
-
 	@LogMessage(level = WARN)
 	@Message(value = "Overriding %s is dangerous, this might break the EJB3 specification implementation", id = 193)
 	void overridingTransactionStrategyDangerous(String transactionStrategy);
@@ -307,22 +242,6 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "'hibernate.properties' not found", id = 206)
 	void propertiesNotFound();
 
-	@LogMessage(level = INFO)
-	@Message(value = "Queries executed to database: %s", id = 210)
-	void queriesExecuted(long queryExecutionCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Query cache hits: %s", id = 213)
-	void queryCacheHits(long queryCacheHitCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Query cache misses: %s", id = 214)
-	void queryCacheMisses(long queryCacheMissCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Query cache puts: %s", id = 215)
-	void queryCachePuts(long queryCachePutCount);
-
 	@LogMessage(level = INFO)
 	@Message(value = "Reading mappings from cache file: %s", id = 219)
 	void readingCachedMappings(File cachedFile);
@@ -354,26 +273,6 @@ public interface CoreMessageLogger extends BasicLogger {
 			SessionFactoryImplementor factory,
 			SessionFactoryImplementor factory2);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Second level cache hits: %s", id = 237)
-	void secondLevelCacheHits(long secondLevelCacheHitCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Second level cache misses: %s", id = 238)
-	void secondLevelCacheMisses(long secondLevelCacheMissCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Second level cache puts: %s", id = 239)
-	void secondLevelCachePuts(long secondLevelCachePutCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Sessions closed: %s", id = 241)
-	void sessionsClosed(long sessionCloseCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Sessions opened: %s", id = 242)
-	void sessionsOpened(long sessionOpenCount);
-
 	@LogMessage(level = WARN)
 	@Message(value = "SQL Error: %s, SQLState: %s", id = 247)
 	void sqlWarning(int errorCode, String sqlState);
@@ -382,27 +281,13 @@ public interface CoreMessageLogger extends BasicLogger {
 	@Message(value = "Start time: %s", id = 251)
 	void startTime(long startTime);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Statements closed: %s", id = 252)
-	void statementsClosed(long closeStatementCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Statements prepared: %s", id = 253)
-	void statementsPrepared(long prepareStatementCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Successful transactions: %s", id = 258)
-	void successfulTransactions(long committedTransactionCount);
-
 	@LogMessage(level = INFO)
 	@Message(value = "Synchronization [%s] was already registered", id = 259)
 	void synchronizationAlreadyRegistered(Synchronization synchronization);
 
 	@LogMessage(level = ERROR)
 	@Message(value = "Exception calling user Synchronization [%s]: %s", id = 260)
-	void synchronizationFailed(
+	void synchronizationFailed(Synchronization synchronization, Throwable t);
-			Synchronization synchronization,
-			Throwable t);
 
 	@LogMessage(level = INFO)
 	@Message(value = "Table not found: %s", id = 262)
@@ -579,12 +464,9 @@ public interface CoreMessageLogger extends BasicLogger {
 	void unregisteredStatement();
 
 	@LogMessage(level = WARN)
-	@Message(value = "The %s.%s.%s version of H2 implements temporary table creation such that it commits current transaction; multi-table, bulk hql/jpaql will not work properly",
+	@Message(value = "The %s.%s.%s version of H2 implements temporary table creation such that it commits current transaction; multi-table, bulk HQL/JPQL will not work properly",
 			id = 393)
-	void unsupportedMultiTableBulkHqlJpaql(
+	void unsupportedMultiTableBulkHqlJpaql(int majorVersion, int minorVersion, int buildId);
-			int majorVersion,
-			int minorVersion,
-			int buildId);
 
 	@LogMessage(level = INFO)
 	@Message(value = "Explicit segment value for id generator [%s.%s] suggested; using default [%s]", id = 398)
@@ -612,49 +494,24 @@ public interface CoreMessageLogger extends BasicLogger {
 	void writeLocksNotSupported(String entityName);
 
 	@LogMessage(level = DEBUG)
-	@Message(value = "Closing un-released batch", id = 420)
+	@Message(value = "Closing unreleased batch", id = 420)
 	void closingUnreleasedBatch();
 
-	@LogMessage(level = INFO)
-	@Message(value = "update timestamps cache puts: %s", id = 433)
-	void timestampCachePuts(long updateTimestampsCachePutCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "update timestamps cache hits: %s", id = 434)
-	void timestampCacheHits(long updateTimestampsCachePutCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "update timestamps cache misses: %s", id = 435)
-	void timestampCacheMisses(long updateTimestampsCachePutCount);
-
 	@LogMessage(level = WARN)
-	@Message(value = "Attempting to save one or more entities that have a non-nullable association with an unsaved transient entity. The unsaved transient entity must be saved in an operation prior to saving these dependent entities.\n" +
+	@Message(
-			"\tUnsaved transient entity: (%s)\n\tDependent entities: (%s)\n\tNon-nullable association(s): (%s)", id = 437)
+			id = 437,
+			value = """
+					Attempting to save one or more entities that have a non-nullable association with an unsaved transient entity.
+					The unsaved transient entity must be saved in an operation prior to saving these dependent entities.
+						Unsaved transient entity: %s
+						Dependent entities: %s
+						Non-nullable associations: %s"""
+	)
 	void cannotResolveNonNullableTransientDependencies(
 			String transientEntityString,
 			Set<String> dependentEntityStrings,
 			Set<String> nonNullableAssociationPaths);
 
-	@LogMessage(level = INFO)
-	@Message(value = "NaturalId cache puts: %s", id = 438)
-	void naturalIdCachePuts(long naturalIdCachePutCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "NaturalId cache hits: %s", id = 439)
-	void naturalIdCacheHits(long naturalIdCacheHitCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "NaturalId cache misses: %s", id = 440)
-	void naturalIdCacheMisses(long naturalIdCacheMissCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Max NaturalId query time: %sms", id = 441)
-	void naturalIdMaxQueryTime(long naturalIdQueryExecutionMaxTime);
-
-	@LogMessage(level = INFO)
-	@Message(value = "NaturalId queries executed to database: %s", id = 442)
-	void naturalIdQueriesExecuted(long naturalIdQueriesExecutionCount);
-
 	@LogMessage(level = WARN)
 	@Message(
 			value = "Dialect [%s] limits the number of elements in an IN predicate to %s entries.  " +
@@ -774,14 +631,6 @@ public interface CoreMessageLogger extends BasicLogger {
 			"@OneToOne associations mapped with @NotFound are forced to EAGER fetching.", id = 491)
 	void ignoreNotFoundWithFetchTypeLazy(String entity, String association);
 
-	@LogMessage(level = INFO)
-	@Message(value = "Query plan cache hits: %s", id = 492)
-	void queryPlanCacheHits(long queryPlanCacheHitCount);
-
-	@LogMessage(level = INFO)
-	@Message(value = "Query plan cache misses: %s", id = 493)
-	void queryPlanCacheMisses(long queryPlanCacheMissCount);
-
 	@LogMessage(level = WARN)
 	@Message(value = "Attempt to merge an uninitialized collection with queued operations; queued operations will be ignored: %s", id = 494)
 	void ignoreQueuedOperationsOnMerge(String collectionInfoString);
@@ -890,7 +739,7 @@ public interface CoreMessageLogger extends BasicLogger {
 
 	@LogMessage(level = DEBUG)
 	@Message(
-			id = 425,
+			id = 401,
 			value = """
 					Logging session metrics:
 						%s ns acquiring %s JDBC connections
@@ -933,4 +782,77 @@ public interface CoreMessageLogger extends BasicLogger {
 			int partialFlushCount,
 			long partialFlushEntityCount,
 			long partialFlushCollectionCount);
+
+	@LogMessage(level = INFO)
+	@Message(
+			id = 400,
+			value = """
+					Logging statistics:
+						Start time: %s
+						Sessions opened (closed): %s (%s)
+						Transactions started (successful): %s (%s)
+						Optimistic lock failures: %s
+						Flushes: %s
+						Connections obtained: %s
+						Statements prepared (closed): %s (%s)
+						Second-level cache puts: %s
+						Second-level cache hits (misses): %s (%s)
+						Entities loaded: %s
+						Entities fetched: %s (minimize this)
+						Entities updated, inserted, deleted: %s, %s, %s
+						Collections loaded: %s
+						Collections fetched: %s (minimize this)
+						Collections updated, removed, recreated: %s, %s, %s
+						Natural id queries executed on database: %s
+						Natural id cache puts: %s
+						Natural id cache hits (misses): %s (%s)
+						Max natural id query execution time: %s ms
+						Queries executed on database: %s
+						Query cache puts: %s
+						Query cache hits (misses): %s (%s)
+						Max query execution time: %s ms
+						Update timestamps cache puts: %s
+						Update timestamps cache hits (misses): %s (%s)
+						Query plan cache hits (misses): %s (%s)
+					"""
+	)
+	void logStatistics(
+			long startTime,
+			long sessionOpenCount,
+			long sessionCloseCount,
+			long transactionCount,
+			long committedTransactionCount,
+			long optimisticFailureCount,
+			long flushCount,
+			long connectCount,
+			long prepareStatementCount,
+			long closeStatementCount,
+			long secondLevelCachePutCount,
+			long secondLevelCacheHitCount,
+			long secondLevelCacheMissCount,
+			long entityLoadCount,
+			long entityFetchCount,
+			long entityUpdateCount,
+			long entityInsertCount,
+			long entityDeleteCount,
+			long collectionLoadCount,
+			long collectionFetchCount,
+			long collectionUpdateCount,
+			long collectionRemoveCount,
+			long collectionRecreateCount,
+			long naturalIdQueryExecutionCount,
+			long naturalIdCachePutCount,
+			long naturalIdCacheHitCount,
+			long naturalIdCacheMissCount,
+			long naturalIdQueryExecutionMaxTime,
+			long queryExecutionCount,
+			long queryCachePutCount,
+			long queryCacheHitCount,
+			long queryCacheMissCount,
+			long queryExecutionMaxTime,
+			long updateTimestampsCachePutCount,
+			long updateTimestampsCacheHitCount,
+			long updateTimestampsCacheMissCount,
+			long queryPlanCacheHitCount,
+			long queryPlanCacheMissCount);
 }

hibernate-core/src/main/java/org/hibernate/stat/internal/StatisticsImpl.java

@@ -890,45 +890,46 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 
 	@Override
 	public void logSummary() {
-		log.loggingStatistics();
+		log.logStatistics(
-		log.startTime( startTime.toEpochMilli() );
+				startTime.toEpochMilli(),
-		log.sessionsOpened( sessionOpenCount.sum() );
+				sessionOpenCount.sum(),
-		log.sessionsClosed( sessionCloseCount.sum() );
+				sessionCloseCount.sum(),
-		log.transactions( transactionCount.sum() );
+				transactionCount.sum(),
-		log.successfulTransactions( committedTransactionCount.sum() );
+				committedTransactionCount.sum(),
-		log.optimisticLockFailures( optimisticFailureCount.sum() );
+				optimisticFailureCount.sum(),
-		log.flushes( flushCount.sum() );
+				flushCount.sum(),
-		log.connectionsObtained( connectCount.sum() );
+				connectCount.sum(),
-		log.statementsPrepared( prepareStatementCount.sum() );
+				prepareStatementCount.sum(),
-		log.statementsClosed( closeStatementCount.sum() );
+				closeStatementCount.sum(),
-		log.secondLevelCachePuts( secondLevelCachePutCount.sum() );
+				secondLevelCachePutCount.sum(),
-		log.secondLevelCacheHits( secondLevelCacheHitCount.sum() );
+				secondLevelCacheHitCount.sum(),
-		log.secondLevelCacheMisses( secondLevelCacheMissCount.sum() );
+				secondLevelCacheMissCount.sum(),
-		log.entitiesLoaded( entityLoadCount.sum() );
+				entityLoadCount.sum(),
-		log.entitiesUpdated( entityUpdateCount.sum() );
+				entityFetchCount.sum(),
-		log.entitiesInserted( entityInsertCount.sum() );
+				entityUpdateCount.sum(),
-		log.entitiesDeleted( entityDeleteCount.sum() );
+				entityInsertCount.sum(),
-		log.entitiesFetched( entityFetchCount.sum() );
+				entityDeleteCount.sum(),
-		log.collectionsLoaded( collectionLoadCount.sum() );
+				collectionLoadCount.sum(),
-		log.collectionsUpdated( collectionUpdateCount.sum() );
+				collectionFetchCount.sum(),
-		log.collectionsRemoved( collectionRemoveCount.sum() );
+				collectionUpdateCount.sum(),
-		log.collectionsRecreated( collectionRecreateCount.sum() );
+				collectionRemoveCount.sum(),
-		log.collectionsFetched( collectionFetchCount.sum() );
+				collectionRecreateCount.sum(),
-		log.naturalIdCachePuts( naturalIdCachePutCount.sum() );
+				naturalIdQueryExecutionCount.sum(),
-		log.naturalIdCacheHits( naturalIdCacheHitCount.sum() );
+				naturalIdCachePutCount.sum(),
-		log.naturalIdCacheMisses( naturalIdCacheMissCount.sum() );
+				naturalIdCacheHitCount.sum(),
-		log.naturalIdMaxQueryTime( naturalIdQueryExecutionMaxTime.get() );
+				naturalIdCacheMissCount.sum(),
-		log.naturalIdQueriesExecuted( naturalIdQueryExecutionCount.sum() );
+				naturalIdQueryExecutionMaxTime.get(),
-		log.queriesExecuted( queryExecutionCount.sum() );
+				queryExecutionCount.sum(),
-		log.queryCachePuts( queryCachePutCount.sum() );
+				queryCachePutCount.sum(),
-		log.timestampCachePuts( updateTimestampsCachePutCount.sum() );
+				queryCacheHitCount.sum(),
-		log.timestampCacheHits( updateTimestampsCacheHitCount.sum() );
+				queryCacheMissCount.sum(),
-		log.timestampCacheMisses( updateTimestampsCacheMissCount.sum() );
+				queryExecutionMaxTime.get(),
-		log.queryCacheHits( queryCacheHitCount.sum() );
+				updateTimestampsCachePutCount.sum(),
-		log.queryCacheMisses( queryCacheMissCount.sum() );
+				updateTimestampsCacheHitCount.sum(),
-		log.maxQueryTime( queryExecutionMaxTime.get() );
+				updateTimestampsCacheMissCount.sum(),
-		log.queryPlanCacheHits( queryPlanCacheHitCount.sum() );
+				queryPlanCacheHitCount.sum(),
-		log.queryPlanCacheMisses( queryPlanCacheMissCount.sum() );
+				queryPlanCacheMissCount.sum()
+		);
 	}
 
 	@Override

hibernate-testing/src/test/java/org/hibernate/testing/logger/LoggingRuleTest.java

@@ -33,9 +33,9 @@ public class LoggingRuleTest {
 
 	@Test
 	public void testRule() {
-		Triggerable triggerable = logInspection.watchForLogMessages( "HHH000008:" );
+		Triggerable triggerable = logInspection.watchForLogMessages( "HHH000229:" );
 		Assert.assertFalse( triggerable.wasTriggered() );
-		LOG.autoFlushWillNotWork(); //Uses code HHH000008
+		LOG.runningSchemaValidator(); //Uses code HHH000229
 		Assert.assertTrue( triggerable.wasTriggered() );
 		triggerable.reset();
 		Assert.assertFalse( triggerable.wasTriggered() );