From aae5333dc4f632971039767519e77a2129349caa Mon Sep 17 00:00:00 2001 From: Gavin King Date: Wed, 4 Dec 2024 02:14:20 +0100 Subject: [PATCH] HHH-18907 improve how statistics are logged --- .../hibernate/internal/CoreMessageLogger.java | 252 ++++++------------ .../stat/internal/StatisticsImpl.java | 79 +++--- .../testing/logger/LoggingRuleTest.java | 4 +- 3 files changed, 129 insertions(+), 206 deletions(-) diff --git a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java b/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java index 0b58cb496a..ea77fa3dff 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/CoreMessageLogger.java +++ b/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 , 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( - Synchronization synchronization, - Throwable t); + void synchronizationFailed(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( - int majorVersion, - int minorVersion, - int buildId); + void unsupportedMultiTableBulkHqlJpaql(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" + - "\tUnsaved transient entity: (%s)\n\tDependent entities: (%s)\n\tNon-nullable association(s): (%s)", id = 437) + @Message( + 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 dependentEntityStrings, Set 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); } diff --git a/hibernate-core/src/main/java/org/hibernate/stat/internal/StatisticsImpl.java b/hibernate-core/src/main/java/org/hibernate/stat/internal/StatisticsImpl.java index f9e042ed81..d30a34ed82 100644 --- a/hibernate-core/src/main/java/org/hibernate/stat/internal/StatisticsImpl.java +++ b/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.startTime( startTime.toEpochMilli() ); - log.sessionsOpened( sessionOpenCount.sum() ); - log.sessionsClosed( sessionCloseCount.sum() ); - log.transactions( transactionCount.sum() ); - log.successfulTransactions( committedTransactionCount.sum() ); - log.optimisticLockFailures( optimisticFailureCount.sum() ); - log.flushes( flushCount.sum() ); - log.connectionsObtained( connectCount.sum() ); - log.statementsPrepared( prepareStatementCount.sum() ); - log.statementsClosed( closeStatementCount.sum() ); - log.secondLevelCachePuts( secondLevelCachePutCount.sum() ); - log.secondLevelCacheHits( secondLevelCacheHitCount.sum() ); - log.secondLevelCacheMisses( secondLevelCacheMissCount.sum() ); - log.entitiesLoaded( entityLoadCount.sum() ); - log.entitiesUpdated( entityUpdateCount.sum() ); - log.entitiesInserted( entityInsertCount.sum() ); - log.entitiesDeleted( entityDeleteCount.sum() ); - log.entitiesFetched( entityFetchCount.sum() ); - log.collectionsLoaded( collectionLoadCount.sum() ); - log.collectionsUpdated( collectionUpdateCount.sum() ); - log.collectionsRemoved( collectionRemoveCount.sum() ); - log.collectionsRecreated( collectionRecreateCount.sum() ); - log.collectionsFetched( collectionFetchCount.sum() ); - log.naturalIdCachePuts( naturalIdCachePutCount.sum() ); - log.naturalIdCacheHits( naturalIdCacheHitCount.sum() ); - log.naturalIdCacheMisses( naturalIdCacheMissCount.sum() ); - log.naturalIdMaxQueryTime( naturalIdQueryExecutionMaxTime.get() ); - log.naturalIdQueriesExecuted( naturalIdQueryExecutionCount.sum() ); - log.queriesExecuted( queryExecutionCount.sum() ); - log.queryCachePuts( queryCachePutCount.sum() ); - log.timestampCachePuts( updateTimestampsCachePutCount.sum() ); - log.timestampCacheHits( updateTimestampsCacheHitCount.sum() ); - log.timestampCacheMisses( updateTimestampsCacheMissCount.sum() ); - log.queryCacheHits( queryCacheHitCount.sum() ); - log.queryCacheMisses( queryCacheMissCount.sum() ); - log.maxQueryTime( queryExecutionMaxTime.get() ); - log.queryPlanCacheHits( queryPlanCacheHitCount.sum() ); - log.queryPlanCacheMisses( queryPlanCacheMissCount.sum() ); + log.logStatistics( + startTime.toEpochMilli(), + sessionOpenCount.sum(), + sessionCloseCount.sum(), + transactionCount.sum(), + committedTransactionCount.sum(), + optimisticFailureCount.sum(), + flushCount.sum(), + connectCount.sum(), + prepareStatementCount.sum(), + closeStatementCount.sum(), + secondLevelCachePutCount.sum(), + secondLevelCacheHitCount.sum(), + secondLevelCacheMissCount.sum(), + entityLoadCount.sum(), + entityFetchCount.sum(), + entityUpdateCount.sum(), + entityInsertCount.sum(), + entityDeleteCount.sum(), + collectionLoadCount.sum(), + collectionFetchCount.sum(), + collectionUpdateCount.sum(), + collectionRemoveCount.sum(), + collectionRecreateCount.sum(), + naturalIdQueryExecutionCount.sum(), + naturalIdCachePutCount.sum(), + naturalIdCacheHitCount.sum(), + naturalIdCacheMissCount.sum(), + naturalIdQueryExecutionMaxTime.get(), + queryExecutionCount.sum(), + queryCachePutCount.sum(), + queryCacheHitCount.sum(), + queryCacheMissCount.sum(), + queryExecutionMaxTime.get(), + updateTimestampsCachePutCount.sum(), + updateTimestampsCacheHitCount.sum(), + updateTimestampsCacheMissCount.sum(), + queryPlanCacheHitCount.sum(), + queryPlanCacheMissCount.sum() + ); } @Override diff --git a/hibernate-testing/src/test/java/org/hibernate/testing/logger/LoggingRuleTest.java b/hibernate-testing/src/test/java/org/hibernate/testing/logger/LoggingRuleTest.java index bf866c22fc..f09ed1a9ae 100644 --- a/hibernate-testing/src/test/java/org/hibernate/testing/logger/LoggingRuleTest.java +++ b/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() );