diff --git a/hibernate-core/src/main/java/org/hibernate/BaseSessionEventListener.java b/hibernate-core/src/main/java/org/hibernate/BaseSessionEventListener.java index a8fdcd1b336c..6d0222d6094e 100644 --- a/hibernate-core/src/main/java/org/hibernate/BaseSessionEventListener.java +++ b/hibernate-core/src/main/java/org/hibernate/BaseSessionEventListener.java @@ -5,97 +5,14 @@ package org.hibernate; /** - * A no-op implementation of SessionEventListener. Intended as a convenient base class for developing - * SessionEventListener implementations. + * A noop implementation of {@link SessionEventListener}. + * Intended as a convenient base class for developing + * {@code SessionEventListener} implementations. * * @author Steve Ebersole + * + * @deprecated Just implement {@link SessionEventListener} directly. */ +@Deprecated(since = "7", forRemoval = true) public class BaseSessionEventListener implements SessionEventListener { - @Override - public void transactionCompletion(boolean successful) { - } - - @Override - public void jdbcConnectionAcquisitionStart() { - } - - @Override - public void jdbcConnectionAcquisitionEnd() { - } - - @Override - public void jdbcConnectionReleaseStart() { - } - - @Override - public void jdbcConnectionReleaseEnd() { - } - - @Override - public void jdbcPrepareStatementStart() { - } - - @Override - public void jdbcPrepareStatementEnd() { - } - - @Override - public void jdbcExecuteStatementStart() { - } - - @Override - public void jdbcExecuteStatementEnd() { - } - - @Override - public void jdbcExecuteBatchStart() { - } - - @Override - public void jdbcExecuteBatchEnd() { - } - - @Override - public void cachePutStart() { - } - - @Override - public void cachePutEnd() { - } - - @Override - public void cacheGetStart() { - } - - @Override - public void cacheGetEnd(boolean hit) { - } - - @Override - public void flushStart() { - } - - @Override - public void flushEnd(int numberOfEntities, int numberOfCollections) { - } - - @Override - public void partialFlushStart() { - } - - @Override - public void partialFlushEnd(int numberOfEntities, int numberOfCollections) { - } - - @Override - public void dirtyCalculationStart() { - } - - @Override - public void dirtyCalculationEnd(boolean dirty) { - } - - @Override - public void end() { - } } diff --git a/hibernate-core/src/main/java/org/hibernate/SessionEventListener.java b/hibernate-core/src/main/java/org/hibernate/SessionEventListener.java index bbc4d4d0d32f..b486d16ff93f 100644 --- a/hibernate-core/src/main/java/org/hibernate/SessionEventListener.java +++ b/hibernate-core/src/main/java/org/hibernate/SessionEventListener.java @@ -15,8 +15,8 @@ * sessions may be registered using the configuration property * {@value org.hibernate.cfg.AvailableSettings#AUTO_SESSION_EVENTS_LISTENER}. * A new instance of the class will be created for each new session. - *

- * This an incubating API, subject to change. + * + * @apiNote This an incubating API, subject to change. * * @see org.hibernate.cfg.AvailableSettings#AUTO_SESSION_EVENTS_LISTENER * @see SessionBuilder#eventListeners(SessionEventListener...) diff --git a/hibernate-core/src/main/java/org/hibernate/boot/internal/SessionFactoryOptionsBuilder.java b/hibernate-core/src/main/java/org/hibernate/boot/internal/SessionFactoryOptionsBuilder.java index fc19b9f69fc2..a05a7bc8414a 100644 --- a/hibernate-core/src/main/java/org/hibernate/boot/internal/SessionFactoryOptionsBuilder.java +++ b/hibernate-core/src/main/java/org/hibernate/boot/internal/SessionFactoryOptionsBuilder.java @@ -100,7 +100,6 @@ import static org.hibernate.cfg.AvailableSettings.JDBC_TIME_ZONE; import static org.hibernate.cfg.AvailableSettings.JPA_CALLBACKS_ENABLED; import static org.hibernate.cfg.AvailableSettings.JTA_TRACK_BY_THREAD; -import static org.hibernate.cfg.AvailableSettings.LOG_SESSION_METRICS; import static org.hibernate.cfg.AvailableSettings.MAX_FETCH_DEPTH; import static org.hibernate.cfg.AvailableSettings.MULTI_TENANT_IDENTIFIER_RESOLVER; import static org.hibernate.cfg.AvailableSettings.ORDER_INSERTS; @@ -357,8 +356,7 @@ public SessionFactoryOptionsBuilder(StandardServiceRegistry serviceRegistry, Boo ? null : strategySelector.selectStrategyImplementor( SessionEventListener.class, autoSessionEventsListenerName ); - final boolean logSessionMetrics = configurationService.getSetting( LOG_SESSION_METRICS, BOOLEAN, statisticsEnabled ); - this.baselineSessionEventsListenerBuilder = new BaselineSessionEventsListenerBuilder( logSessionMetrics, autoSessionEventsListener ); + this.baselineSessionEventsListenerBuilder = new BaselineSessionEventsListenerBuilder( autoSessionEventsListener ); this.customEntityDirtinessStrategy = strategySelector.resolveDefaultableStrategy( CustomEntityDirtinessStrategy.class, diff --git a/hibernate-core/src/main/java/org/hibernate/cache/spi/SecondLevelCacheLogger.java b/hibernate-core/src/main/java/org/hibernate/cache/spi/SecondLevelCacheLogger.java index 119c4910da03..f81c86476f5f 100644 --- a/hibernate-core/src/main/java/org/hibernate/cache/spi/SecondLevelCacheLogger.java +++ b/hibernate-core/src/main/java/org/hibernate/cache/spi/SecondLevelCacheLogger.java @@ -84,6 +84,7 @@ public interface SecondLevelCacheLogger extends BasicLogger { " You can disable this warning by setting '%2$s' to '%3$s'.", id = NAMESPACE + 6 ) + @SuppressWarnings( "unused" ) // used by hibernate-jcache void missingCacheCreated(String regionName, String configurationPropertyToDisableKey, String configurationPropertyToDisableValue); @LogMessage(level = WARN) @@ -92,6 +93,7 @@ public interface SecondLevelCacheLogger extends BasicLogger { " Update your configuration to rename cache [%2$s] to [%1$s].", id = NAMESPACE + 7 ) + @SuppressWarnings( "unused" ) // used by hibernate-jcache void usingLegacyCacheName(String currentName, String legacyName); @LogMessage(level = WARN) @@ -100,6 +102,7 @@ public interface SecondLevelCacheLogger extends BasicLogger { " Make sure your cache implementation supports JTA transactions.", id = NAMESPACE + 8 ) + @SuppressWarnings( "unused" ) // used by hibernate-jcache void nonStandardSupportForAccessType(String key, String accessType, String regionName); } diff --git a/hibernate-core/src/main/java/org/hibernate/cfg/PersistenceSettings.java b/hibernate-core/src/main/java/org/hibernate/cfg/PersistenceSettings.java index 6039dd56dc2a..78a2f2e0a27e 100644 --- a/hibernate-core/src/main/java/org/hibernate/cfg/PersistenceSettings.java +++ b/hibernate-core/src/main/java/org/hibernate/cfg/PersistenceSettings.java @@ -134,7 +134,6 @@ public interface PersistenceSettings { * * @see #SCANNER * @see org.hibernate.boot.archive.scan.spi.Scanner - * @see org.hibernate.boot.archive.scan.spi.AbstractScannerImpl * @see org.hibernate.boot.MetadataBuilder#applyArchiveDescriptorFactory */ String SCANNER_ARCHIVE_INTERPRETER = "hibernate.archive.interpreter"; diff --git a/hibernate-core/src/main/java/org/hibernate/cfg/SessionEventSettings.java b/hibernate-core/src/main/java/org/hibernate/cfg/SessionEventSettings.java index adad86ddf5dd..19b575d81659 100644 --- a/hibernate-core/src/main/java/org/hibernate/cfg/SessionEventSettings.java +++ b/hibernate-core/src/main/java/org/hibernate/cfg/SessionEventSettings.java @@ -13,18 +13,6 @@ */ public interface SessionEventSettings { - /** - * Controls whether {@linkplain org.hibernate.stat.SessionStatistics session metrics} - * should be {@linkplain org.hibernate.engine.internal.StatisticalLoggingSessionEventListener - * logged} for any session in which statistics are being collected. - *

- * By default, logging of session metrics is disabled unless {@link StatisticsSettings#GENERATE_STATISTICS} - * is enabled. - * - * @settingDefault Defined by {@link StatisticsSettings#GENERATE_STATISTICS} - */ - String LOG_SESSION_METRICS = "hibernate.session.events.log"; - /** * Defines a default {@link org.hibernate.SessionEventListener} to be applied to * newly-opened {@link org.hibernate.Session}s. @@ -75,4 +63,12 @@ public interface SessionEventSettings { * @since 5.2 */ String SESSION_SCOPED_INTERCEPTOR = "hibernate.session_factory.session_scoped_interceptor"; + + /** + * @deprecated This setting is now ignored. Enable the log category + * {@code org.hibernate.session.metrics} to automatically + * collect and log session-level metrics. + */ + @Deprecated(since = "7", forRemoval = true) + String LOG_SESSION_METRICS = "hibernate.session.events.log"; } diff --git a/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java b/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java index 433ec03aed7a..5a0b52bbb33d 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java +++ b/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java @@ -4,17 +4,18 @@ */ package org.hibernate.engine.internal; -import org.hibernate.BaseSessionEventListener; +import org.hibernate.SessionEventListener; +import org.hibernate.internal.CoreMessageLogger; -import org.jboss.logging.Logger; +import static org.hibernate.internal.CoreLogging.messageLogger; /** - * @see org.hibernate.cfg.AvailableSettings#LOG_SESSION_METRICS + * Tracks and logs certain session-level metrics. * * @author Steve Ebersole */ -public class StatisticalLoggingSessionEventListener extends BaseSessionEventListener { - private static final Logger log = Logger.getLogger( StatisticalLoggingSessionEventListener.class ); +public class StatisticalLoggingSessionEventListener implements SessionEventListener { + private static final CoreMessageLogger log = messageLogger( "org.hibernate.session.metrics" ); /** * Used by SettingsFactory (in conjunction with stats being enabled) to determine whether to apply this listener @@ -22,7 +23,7 @@ public class StatisticalLoggingSessionEventListener extends BaseSessionEventList * @return {@code true} if logging is enabled for this listener. */ public static boolean isLoggingEnabled() { - return log.isInfoEnabled(); + return log.isDebugEnabled(); } // cumulative state ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -274,21 +275,8 @@ public void partialFlushEnd(int numberOfEntities, int numberOfCollections) { @Override public void end() { - if ( log.isInfoEnabled() ) { - log.infof( - "Session Metrics {\n" + - " %s nanoseconds spent acquiring %s JDBC connections;\n" + - " %s nanoseconds spent releasing %s JDBC connections;\n" + - " %s nanoseconds spent preparing %s JDBC statements;\n" + - " %s nanoseconds spent executing %s JDBC statements;\n" + - " %s nanoseconds spent executing %s JDBC batches;\n" + - " %s nanoseconds spent performing %s L2C puts;\n" + - " %s nanoseconds spent performing %s L2C hits;\n" + - " %s nanoseconds spent performing %s L2C misses;\n" + - " %s nanoseconds spent executing %s flushes (flushing a total of %s entities and %s collections);\n" + - " %s nanoseconds spent executing %s pre-partial-flushes;\n" + - " %s nanoseconds spent executing %s partial-flushes (flushing a total of %s entities and %s collections)\n" + - "}", + if ( isLoggingEnabled() ) { + log.sessionMetrics( jdbcConnectionAcquisitionTime, jdbcConnectionAcquisitionCount, jdbcConnectionReleaseTime, diff --git a/hibernate-core/src/main/java/org/hibernate/internal/BaselineSessionEventsListenerBuilder.java b/hibernate-core/src/main/java/org/hibernate/internal/BaselineSessionEventsListenerBuilder.java index d550c9b30e57..4e9507a9ebe0 100644 --- a/hibernate-core/src/main/java/org/hibernate/internal/BaselineSessionEventsListenerBuilder.java +++ b/hibernate-core/src/main/java/org/hibernate/internal/BaselineSessionEventsListenerBuilder.java @@ -19,21 +19,12 @@ public class BaselineSessionEventsListenerBuilder { private static final SessionEventListener[] EMPTY = new SessionEventListener[0]; - private final boolean logSessionMetrics; private final Class autoListener; - public BaselineSessionEventsListenerBuilder( - boolean logSessionMetrics, - Class autoListener) { - this.logSessionMetrics = logSessionMetrics; + public BaselineSessionEventsListenerBuilder(Class autoListener) { this.autoListener = autoListener; } - @SuppressWarnings("unused") - public boolean isLogSessionMetrics() { - return logSessionMetrics; - } - @SuppressWarnings("unused") public Class getAutoListener() { return autoListener; @@ -48,24 +39,26 @@ public List buildBaselineList() { } public SessionEventListener[] buildBaseline() { - final boolean addStats = logSessionMetrics && StatisticalLoggingSessionEventListener.isLoggingEnabled(); - final boolean addAutoListener = autoListener != null; final SessionEventListener[] arr; - if ( addStats && addAutoListener ) { - arr = new SessionEventListener[2]; - arr[0] = buildStatsListener(); - arr[1] = buildAutoListener( autoListener ); - } - else if ( !addStats && addAutoListener ) { - arr = new SessionEventListener[1]; - arr[0] = buildAutoListener( autoListener ); - } - else if ( addStats && !addAutoListener ) { - arr = new SessionEventListener[1]; - arr[0] = buildStatsListener(); + if ( autoListener != null ) { + if ( StatisticalLoggingSessionEventListener.isLoggingEnabled() ) { + arr = new SessionEventListener[2]; + arr[0] = buildStatsListener(); + arr[1] = buildAutoListener( autoListener ); + } + else { + arr = new SessionEventListener[1]; + arr[0] = buildAutoListener( autoListener ); + } } - else {//if ( !addStats && !addAutoListener ) - arr = EMPTY; + else { + if ( StatisticalLoggingSessionEventListener.isLoggingEnabled() ) { + arr = new SessionEventListener[1]; + arr[0] = buildStatsListener(); + } + else { + arr = EMPTY; + } } return arr; } @@ -76,7 +69,7 @@ private static SessionEventListener buildAutoListener(final Class, 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 @@ void expectedType(String name, + " 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 @@ void honoringOptimizerSetting( @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 @@ void missingArguments( 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 @@ void missingArguments( @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 @@ void scopingTypesToSessionFactoryAfterAlreadyScoped( 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 @@ void scopingTypesToSessionFactoryAfterAlreadyScoped( @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 @@ void synchronizationFailed( 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 @@ void unsupportedMultiTableBulkHqlJpaql( 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 @@ void cannotResolveNonNullableTransientDependencies( "@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); @@ -887,4 +736,123 @@ void unableToLocateStaticMetamodelField( value = "Encountered multiple persistence-unit stanzas defining same name [%s]; persistence-unit names must be unique" ) void duplicatedPersistenceUnitName(String name); + + @LogMessage(level = DEBUG) + @Message( + id = 401, + value = """ + Logging session metrics: + %s ns acquiring %s JDBC connections + %s ns releasing %s JDBC connections + %s ns preparing %s JDBC statements + %s ns executing %s JDBC statements + %s ns executing %s JDBC batches + %s ns performing %s second-level cache puts + %s ns performing %s second-level cache hits + %s ns performing %s second-level cache misses + %s ns executing %s flushes (flushing a total of %s entities and %s collections) + %s ns executing %s pre-partial-flushes + %s ns executing %s partial-flushes (flushing a total of %s entities and %s collections) + """ + ) + void sessionMetrics( + long jdbcConnectionAcquisitionTime, + int jdbcConnectionAcquisitionCount, + long jdbcConnectionReleaseTime, + int jdbcConnectionReleaseCount, + long jdbcPrepareStatementTime, + int jdbcPrepareStatementCount, + long jdbcExecuteStatementTime, + int jdbcExecuteStatementCount, + long jdbcExecuteBatchTime, + int jdbcExecuteBatchCount, + long cachePutTime, + int cachePutCount, + long cacheHitTime, + int cacheHitCount, + long cacheMissTime, + int cacheMissCount, + long flushTime, + int flushCount, + long flushEntityCount, + long flushCollectionCount, + long prePartialFlushTime, + int prePartialFlushCount, + long partialFlushTime, + 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 e5e3347e5785..d30a34ed82db 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 @@ -42,7 +42,7 @@ */ public class StatisticsImpl implements StatisticsImplementor, Service { - private static final CoreMessageLogger LOG = messageLogger( StatisticsImpl.class ); + private static final CoreMessageLogger log = messageLogger( StatisticsImpl.class ); private final MappingMetamodelImplementor metamodel; private final CacheImplementor cache; @@ -702,7 +702,7 @@ public long getQueryExecutionMaxTime() { @Override public void queryExecuted(String hql, int rows, long time) { - LOG.hql( hql, time, (long) rows ); + log.hql( hql, time, (long) rows ); queryExecutionCount.increment(); boolean isLongestQuery; @@ -724,7 +724,7 @@ public void queryExecuted(String hql, int rows, long time) { @Override public void queryCacheHit(String hql, String regionName) { - LOG.tracef( "Statistics#queryCacheHit( `%s`, `%s` )", hql, regionName ); + log.tracef( "Statistics#queryCacheHit( `%s`, `%s` )", hql, regionName ); queryCacheHitCount.increment(); @@ -737,7 +737,7 @@ public void queryCacheHit(String hql, String regionName) { @Override public void queryCacheMiss(String hql, String regionName) { - LOG.tracef( "Statistics#queryCacheMiss( `%s`, `%s` )", hql, regionName ); + log.tracef( "Statistics#queryCacheMiss( `%s`, `%s` )", hql, regionName ); queryCacheMissCount.increment(); @@ -750,7 +750,7 @@ public void queryCacheMiss(String hql, String regionName) { @Override public void queryCachePut(String hql, String regionName) { - LOG.tracef( "Statistics#queryCachePut( `%s`, `%s` )", hql, regionName ); + log.tracef( "Statistics#queryCachePut( `%s`, `%s` )", hql, regionName ); queryCachePutCount.increment(); @@ -890,45 +890,46 @@ public void endTransaction(boolean success) { @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-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java b/hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java deleted file mode 100644 index e8c9065c691c..000000000000 --- a/hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java +++ /dev/null @@ -1,213 +0,0 @@ -/* - * SPDX-License-Identifier: LGPL-2.1-or-later - * Copyright Red Hat Inc. and Hibernate Authors - */ -package org.hibernate.engine.internal; - -import java.util.List; -import java.util.regex.Matcher; -import java.util.regex.Pattern; - -import org.hibernate.cfg.AvailableSettings; -import org.hibernate.internal.CoreMessageLogger; - -import org.hibernate.testing.logger.LoggerInspectionRule; -import org.hibernate.testing.logger.Triggerable; -import org.hibernate.testing.orm.domain.gambit.BasicEntity; -import org.hibernate.testing.orm.junit.DomainModel; -import org.hibernate.testing.orm.junit.Jira; -import org.hibernate.testing.orm.junit.ServiceRegistry; -import org.hibernate.testing.orm.junit.SessionFactory; -import org.hibernate.testing.orm.junit.SessionFactoryScope; -import org.hibernate.testing.orm.junit.Setting; -import org.junit.Rule; -import org.junit.jupiter.api.Test; - -import org.jboss.logging.Logger; - -import static org.assertj.core.api.Assertions.assertThat; -import static org.junit.jupiter.api.Assertions.assertTrue; - -/** - * @author Christian Bürgi - */ -@DomainModel(annotatedClasses = { - BasicEntity.class -}) -@SessionFactory(generateStatistics = true) -@ServiceRegistry(settings = { - @Setting(name = AvailableSettings.STATEMENT_BATCH_SIZE, value = "10"), - @Setting(name = AvailableSettings.ORDER_INSERTS, value = "true"), - @Setting(name = AvailableSettings.USE_QUERY_CACHE, value = "true"), - @Setting(name = AvailableSettings.USE_SECOND_LEVEL_CACHE, value = "true") -}) -@Jira("https://hibernate.atlassian.net/browse/HHH-18513") -public class StatisticalLoggingSessionEventListenerTest { - - @Rule - public LoggerInspectionRule logInspection = new LoggerInspectionRule( - Logger.getMessageLogger( - CoreMessageLogger.class, - StatisticalLoggingSessionEventListener.class.getName() - ) ); - - @Test - void testSessionMetricsLog(SessionFactoryScope scope) { - Triggerable triggerable = logInspection.watchForLogMessages( "Session Metrics {" ); - long startTime = System.nanoTime(); - - scope.inTransaction( session -> { - session.persist( new BasicEntity( 1, "fooData" ) ); - session.persist( new BasicEntity( 2, "fooData2" ) ); - session.flush(); - session.clear(); - for ( int i = 0; i < 2; i++ ) { - assertThat( session.createQuery( "select data from BasicEntity e where e.id=1", String.class ) - .setCacheable( true ) - .getSingleResult() ).isEqualTo( "fooData" ); - } - } ); - long sessionNanoDuration = System.nanoTime() - startTime; - - List messages = triggerable.triggerMessages(); - assertThat( messages ).hasSize( 1 ); - String sessionMetricsLog = messages.get( 0 ); - - // acquiring JDBC connections - SessionMetric acquiringJdbcConnectionsMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent acquiring ([0-9]+) JDBC connections" - ); - assertThat( acquiringJdbcConnectionsMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // releasing JDBC connections - SessionMetric releasingJdbcConnectionsMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent releasing ([0-9]+) JDBC connections" - ); - assertThat( releasingJdbcConnectionsMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // preparing JDBC statements - SessionMetric preparingJdbcStatmentsMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent preparing ([0-9]+) JDBC statements" - ); - assertThat( preparingJdbcStatmentsMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // executing JDBC statements - SessionMetric executingJdbcStatmentsMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent executing ([0-9]+) JDBC statements" - ); - assertThat( executingJdbcStatmentsMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // executing JDBC batches - SessionMetric executingJdbcBatchesMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent executing ([0-9]+) JDBC batches" - ); - assertThat( executingJdbcBatchesMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // performing L2C puts - SessionMetric performingL2CPutsMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent performing ([0-9]+) L2C puts" - ); - assertThat( performingL2CPutsMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // performing L2C hits - SessionMetric performingL2CHitsMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent performing ([0-9]+) L2C hits" - ); - assertThat( performingL2CHitsMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // performing L2C misses - SessionMetric performingL2CMissesMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent performing ([0-9]+) L2C misses" - ); - assertThat( performingL2CMissesMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // executing flushes - SessionMetric executingFlushesMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent executing ([0-9]+) flushes" - ); - assertThat( executingFlushesMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // executing pre-partial-flushes - SessionMetric executingPrePartialFlushesMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent executing ([0-9]+) pre-partial-flushes" - ); - assertThat( executingPrePartialFlushesMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // executing partial-flushes - SessionMetric executingPartialFlushesMetric = extractMetric( - sessionMetricsLog, - "([0-9]+) nanoseconds spent executing ([0-9]+) partial-flushes" - ); - assertThat( executingPartialFlushesMetric.getDuration() ).isGreaterThan( 0L ) - .isLessThan( sessionNanoDuration ); - - // Number of metrics - List metricList = List.of( - acquiringJdbcConnectionsMetric, - releasingJdbcConnectionsMetric, - preparingJdbcStatmentsMetric, - executingJdbcStatmentsMetric, - executingJdbcBatchesMetric, - performingL2CPutsMetric, - performingL2CHitsMetric, - performingL2CMissesMetric, - executingFlushesMetric, - executingPrePartialFlushesMetric, - executingPartialFlushesMetric - ); - int numberOfMetrics = metricList.size(); - // Number of lines - assertThat( sessionMetricsLog.lines().count() ) - .as( "The StatisticalLoggingSessionEventListener should write a line per metric (" - + numberOfMetrics + " lines) plus a header and a footer (2 lines)" ) - .isEqualTo( numberOfMetrics + 2 ); - // Total time - long sumDuration = metricList.stream().map( SessionMetric::getDuration ).mapToLong( Long::longValue ).sum(); - assertThat( sumDuration ).isLessThanOrEqualTo( sessionNanoDuration ); - } - - private SessionMetric extractMetric(String logMessage, String regex) { - Pattern pattern = Pattern.compile( regex ); - Matcher matcher = pattern.matcher( logMessage ); - assertTrue( matcher.find() ); - return new SessionMetric( Long.parseLong( matcher.group( 1 ) ), Integer.parseInt( matcher.group( 2 ) ) ); - } - - private static class SessionMetric { - private final long duration; - private final int count; - - public SessionMetric(long duration, int count) { - this.duration = duration; - this.count = count; - } - - public long getDuration() { - return duration; - } - - public int getCount() { - return count; - } - } -} diff --git a/hibernate-core/src/test/java/org/hibernate/orm/test/annotations/collectionelement/recreate/RecreateCollectionTest.java b/hibernate-core/src/test/java/org/hibernate/orm/test/annotations/collectionelement/recreate/RecreateCollectionTest.java index a48db50ee127..1b7043608b46 100644 --- a/hibernate-core/src/test/java/org/hibernate/orm/test/annotations/collectionelement/recreate/RecreateCollectionTest.java +++ b/hibernate-core/src/test/java/org/hibernate/orm/test/annotations/collectionelement/recreate/RecreateCollectionTest.java @@ -6,8 +6,7 @@ import java.util.Date; -import org.hibernate.BaseSessionEventListener; - +import org.hibernate.SessionEventListener; import org.hibernate.testing.orm.junit.JiraKey; import org.hibernate.testing.orm.junit.DomainModel; import org.hibernate.testing.orm.junit.SessionFactory; @@ -29,7 +28,7 @@ @SessionFactory public class RecreateCollectionTest { - private static class StatementsCounterListener extends BaseSessionEventListener { + private static class StatementsCounterListener implements SessionEventListener { int statements; @Override diff --git a/hibernate-core/src/test/java/org/hibernate/orm/test/event/SessionEventListenersManagerTest.java b/hibernate-core/src/test/java/org/hibernate/orm/test/event/SessionEventListenersManagerTest.java index 865464176780..49a31ba17ff6 100644 --- a/hibernate-core/src/test/java/org/hibernate/orm/test/event/SessionEventListenersManagerTest.java +++ b/hibernate-core/src/test/java/org/hibernate/orm/test/event/SessionEventListenersManagerTest.java @@ -4,7 +4,6 @@ */ package org.hibernate.orm.test.event; -import org.hibernate.BaseSessionEventListener; import org.hibernate.SessionEventListener; import org.hibernate.engine.internal.SessionEventListenerManagerImpl; @@ -43,7 +42,7 @@ public void testEmptyListenerAppending() { Assert.assertEquals( "e", sb.toString() ); } - private static class TestSessionEventListener extends BaseSessionEventListener { + private static class TestSessionEventListener implements SessionEventListener { private final StringBuilder sb; private final char theChar; 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 bf866c22fcfc..f09ed1a9ae0a 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() );