system loggers

design/logger_id_ranges.adoc

@@ -1,109 +1,206 @@
-= JBoss Logging ValidIdRange Mapping
+= Logging design
 
-[width="50%",cols=">s,>s,^2m",options="header"]
+== "System"-specific Loggers
+
+The basic idea here is to group log messages into a more logical hierarchy of Logger names for
+the purpose of filtering.
+
+E.g. "org.hibernate.orm.model.mapping" is one such system we define for the purpose of
+grouping hierarchy of loggers names related to specific aspects of the mapping model:
+
+----
+* org.hibernate.orm.model.mapping
+|- * org.hibernate.orm.model.mapping.creation
+\- * org.hibernate.orm.model.mapping....
+----
+
+Just like with normal log filtering, here we'd use these system names in the underlying logger config.
+
+E.g., in our test-suite we've found the following log4j pattern to be great for these systems:
+
+----
+...
+log4j.appender.stdout.layout=org.apache.log4j.PatternLayout
+log4j.appender.stdout.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}(%C{1}:%L) - %m%n
+
+log4j.logger.org.hibernate.orm.model.mapping.creation=trace
+...
+----
+
+An example of output:
+
+----
+09:45:34,713 DEBUG creation(MappingModelCreationProcess:76) - Starting generic post-init callbacks
+09:45:34,713 DEBUG creation(MappingModelCreationProcess$PostInitCallbackEntry:160) - Starting MappingModelCreationProcess.PostInitCallbackEntry processing : EmbeddableMappingType builder : org.hibernate.type.EmbeddedComponentType@69b2f8e5
+09:45:34,714 DEBUG creation(MappingModelCreationProcess$PostInitCallbackEntry:160) - Starting MappingModelCreationProcess.PostInitCallbackEntry processing : Static fetchable list builder : org.hibernate.test.ecid.CompositeIdAssociationsWithEmbeddedCompositeIdTest$Parent
+----
+
+The pattern could use `%c` rather than `%c{1}`.  That approach is much nicer for these system-based names.  However,
+that would be verbose with the more normal pattern of using class name for logger name.
+
+As an example output:
+
+----
+09:45:34,713 DEBUG org.hibernate.orm.model.mapping.creation(MappingModelCreationProcess:76) - Starting generic post-init callbacks
+09:45:34,713 DEBUG org.hibernate.orm.model.mapping.creation(MappingModelCreationProcess$PostInitCallbackEntry:160) - Starting MappingModelCreationProcess.PostInitCallbackEntry processing : EmbeddableMappingType builder : org.hibernate.type.EmbeddedComponentType@69b2f8e5
+09:45:34,714 DEBUG org.hibernate.orm.model.mapping.creation(MappingModelCreationProcess$PostInitCallbackEntry:160) - Starting MappingModelCreationProcess.PostInitCallbackEntry processing : Static fetchable list builder : org.hibernate.test.ecid.CompositeIdAssociationsWithEmbeddedCompositeIdTest$Parent
+----
+
+Typically, a class would be created for each system to hold a shared reference to a singleton Logger instance as
+well as some helper info such as whether DEBUG or TRACE are enabled.  E.g.:
+
+[source,java]
+----
+@MessageLogger( projectCode = "HHH" )
+@ValidIdRange( min = 90005701, max = 90005800 )
+public interface MappingModelCreationLogger extends BasicLogger {
+	String LOGGER_NAME = "org.hibernate.orm.model.mapping.creation";
+
+	MappingModelCreationLogger LOGGER = Logger.getMessageLogger( MappingModelCreationLogger.class, LOGGER_NAME );
+
+	boolean TRACE_ENABLED = LOGGER.isTraceEnabled();
+	boolean DEBUG_ENABLED = LOGGER.isDebugEnabled();
+}
+----
+
+
+== `@ValidIdRange` registry
+
+[width="50%",cols=">s,>s,^2m,^2m",options="header"]
 |===
 |`ValidIdRange#min`
 |`ValidIdRange#max`
+|Channel
 |Logger
 
 |1
 |10000
+|n/a
 |org.hibernate.internal.CoreMessageLogger
 
 |10001
 |15000
+|n/a
 |org.hibernate.c3p0.internal.C3P0MessageLogger (extends ConnectionPoolingLogger)
 
 |15000
 |20000
+|n/a
 |org.hibernate.internal.EntityManagerMessageLogger
 
 |20001
 |25000
+|n/a
 |org.hibernate.cache.ehcache.EhCacheMessageLogger (extends CoreMessageLogger)
 
 |25001
 |30000
+|n/a
 |org.hibernate.envers.internal.EnversMessageLogger
 
 |25001
 |30000
+|n/a
 |org.hibernate.cache.infinispan.util.InfinispanMessageLogger
 
 |30001
 |35000
+|n/a
 |org.hibernate.proxool.internal.ProxoolMessageLogger (extends ConnectionPoolingLogger)
 
 |10000001
 |10001000
+|org.hibernate.orm.url
 |org.hibernate.internal.log.UrlMessageBundle
 
 |10001001
 |10001500
+|org.hibernate.orm.connections.pooling
 |org.hibernate.internal.log.ConnectionPoolingLogger
 
 |10005001
 |10010000
-|org.hibernate.resource.cdi.internal.CdiMessageLogger
+|org.hibernate.orm.beans
+|org.hibernate.resource.beans.internal.BeansMessageLogger
 
 |80000001
 |80001000
+|n/a
 |org.hibernate.spatial.HSMessageLogger
 
 |90000001
 |90001000
+|org.hibernate.orm.deprecation
 |org.hibernate.internal.log.DeprecationLogger
 
 |90001001
 |90002000
+|org.hibernate.orm.cache
 |org.hibernate.cache.spi.SecondLevelCacheLogger
 
 |90002001
 |90003000
+|n/a
 |org.hibernate.internal.log.UnsupportedLogger
 
 |90003001
 |90003500
+|org.hibernate.orm.query
 |org.hibernate.query.spi.QueryLogger
 
 |90003501
 |90004000
+|org.hibernate.orm.query.hql
 |org.hibernate.query.hql.HqlLogger
 
 |90004001
 |90005000
+|org.hibernate.orm.sql.exec
 |org.hibernate.sql.exec.SqlExecLogger
 
 |90005001
 |90005100
-|org.hibernate.sql.results.SqlResultsLogger
+|org.hibernate.orm.sql.results
+|org.hibernate.sql.results.ResultsLogger
 
 |90005101
 |90005200
-|org.hibernate.sql.results.internal.domain.collection.CollectionLoadingLogger
+|org.hibernate.orm.sql.results.loading.collection
+|org.hibernate.sql.results.graph.collection.CollectionLoadingLogger
 
 |90005201
 |90005300
-|org.hibernate.sql.results.internal.domain.entity.EntityLoadingLogger
+|org.hibernate.orm.sql.results.loading.entity
+|org.hibernate.sql.results.graph.entity.EntityLoadingLogger
 
 |90005301
 |90005400
-|org.hibernate.sql.results.internal.domain.embedded.CompositeLoadingLogger
+|org.hibernate.orm.sql.results.loading.composite
+|org.hibernate.sql.results.graph.embeddable.EmbeddableLoadingLogger
 
 |90005401
 |90005500
+|org.hibernate.orm.sql.ast.tree
 |org.hibernate.sql.ast.tree.SqlAstTreeLogger
 
 |90005501
 |90005600
+|org.hibernate.orm.boot.jaxb
 |org.hibernate.boot.jaxb.JaxbLogger
 
 |90005601
 |90005700
+|org.hibernate.envers.boot
 |org.hibernate.envers.boot.EnversBootLogger
 
 |90005701
 |90005800
+|org.hibernate.orm.model.mapping.creation
 |org.hibernate.metamodel.mapping.MappingModelCreationLogger
 
+|90005801
+|90005900
+|org.hibernate.orm.sql.results.loading
+|org.hibernate.sql.results.LoadingLogger
+
 |===

hibernate-core/src/main/java/org/hibernate/boot/archive/internal/ExplodedArchiveDescriptor.java

@@ -21,7 +21,7 @@ import org.hibernate.boot.archive.spi.ArchiveEntry;
 import org.hibernate.boot.archive.spi.ArchiveException;
 import org.hibernate.boot.archive.spi.InputStreamAccess;
 
-import static org.hibernate.internal.log.UrlMessageBundle.URL_LOGGER;
+import static org.hibernate.internal.log.UrlMessageBundle.URL_MESSAGE_LOGGER;
 
 /**
  * Descriptor for exploded (directory) archives
@@ -72,16 +72,16 @@ public class ExplodedArchiveDescriptor extends AbstractArchiveDescriptor {
 			}
 		}
 		catch (URISyntaxException e) {
-			URL_LOGGER.logMalformedUrl( getArchiveUrl(), e );
+			URL_MESSAGE_LOGGER.logMalformedUrl( getArchiveUrl(), e );
 			return null;
 		}
 
 		if ( !archiveUrlDirectory.exists() ) {
-			URL_LOGGER.logFileDoesNotExist( getArchiveUrl() );
+			URL_MESSAGE_LOGGER.logFileDoesNotExist( getArchiveUrl() );
 			return null;
 		}
 		if ( !archiveUrlDirectory.isDirectory() ) {
-			URL_LOGGER.logFileIsNotDirectory( getArchiveUrl() );
+			URL_MESSAGE_LOGGER.logFileIsNotDirectory( getArchiveUrl() );
 			return null;
 		}
 

hibernate-core/src/main/java/org/hibernate/boot/archive/internal/JarFileBasedArchiveDescriptor.java

@@ -24,7 +24,7 @@ import org.hibernate.boot.archive.spi.ArchiveEntryHandler;
 import org.hibernate.boot.archive.spi.ArchiveException;
 import org.hibernate.boot.archive.spi.InputStreamAccess;
 
-import static org.hibernate.internal.log.UrlMessageBundle.URL_LOGGER;
+import static org.hibernate.internal.log.UrlMessageBundle.URL_MESSAGE_LOGGER;
 
 /**
  * An ArchiveDescriptor implementation leveraging the {@link java.util.jar.JarFile} API for processing.
@@ -169,10 +169,10 @@ public class JarFileBasedArchiveDescriptor extends AbstractArchiveDescriptor {
 			}
 		}
 		catch (IOException e) {
-			URL_LOGGER.logUnableToFindFileByUrl( getArchiveUrl(), e );
+			URL_MESSAGE_LOGGER.logUnableToFindFileByUrl( getArchiveUrl(), e );
 		}
 		catch (URISyntaxException e) {
-			URL_LOGGER.logMalformedUrl( getArchiveUrl(), e );
+			URL_MESSAGE_LOGGER.logMalformedUrl( getArchiveUrl(), e );
 		}
 		return null;
 	}

hibernate-core/src/main/java/org/hibernate/boot/archive/internal/JarInputStreamBasedArchiveDescriptor.java

@@ -19,7 +19,7 @@ import org.hibernate.boot.archive.spi.ArchiveEntry;
 import org.hibernate.boot.archive.spi.ArchiveException;
 import org.hibernate.boot.archive.spi.InputStreamAccess;
 
-import static org.hibernate.internal.log.UrlMessageBundle.URL_LOGGER;
+import static org.hibernate.internal.log.UrlMessageBundle.URL_MESSAGE_LOGGER;
 
 /**
  * An ArchiveDescriptor implementation that works on archives accessible through a {@link java.util.jar.JarInputStream}.
@@ -52,7 +52,7 @@ public class JarInputStreamBasedArchiveDescriptor extends AbstractArchiveDescrip
 		}
 		catch (Exception e) {
 			//really should catch IOException but Eclipse is buggy and raise NPE...
-			URL_LOGGER.logUnableToFindFileByUrl( getArchiveUrl(), e );
+			URL_MESSAGE_LOGGER.logUnableToFindFileByUrl( getArchiveUrl(), e );
 			return;
 		}
 

hibernate-core/src/main/java/org/hibernate/engine/jdbc/connections/internal/DriverManagerConnectionProviderImpl.java

@@ -35,6 +35,7 @@ import org.hibernate.service.spi.ServiceRegistryImplementor;
 import org.hibernate.service.spi.Stoppable;
 
 import static org.hibernate.internal.log.ConnectionPoolingLogger.CONNECTIONS_LOGGER;
+import static org.hibernate.internal.log.ConnectionPoolingLogger.CONNECTIONS_MESSAGE_LOGGER;
 
 /**
  * A connection provider that uses the {@link java.sql.DriverManager} directly to open connections and provides
@@ -69,7 +70,7 @@ public class DriverManagerConnectionProviderImpl
 
 	@Override
 	public void configure(Map configurationValues) {
-		CONNECTIONS_LOGGER.usingHibernateBuiltInConnectionPool();
+		CONNECTIONS_MESSAGE_LOGGER.usingHibernateBuiltInConnectionPool();
 		PooledConnections pool = buildPool( configurationValues, serviceRegistry );
 		final long validationInterval = ConfigurationHelper.getLong( VALIDATION_INTERVAL, configurationValues, 30 );
 		PoolState newstate = new PoolState( pool, validationInterval );
@@ -130,11 +131,11 @@ public class DriverManagerConnectionProviderImpl
 		}
 
 		if ( success ) {
-			CONNECTIONS_LOGGER.loadedDriver( driverClassName );
+			CONNECTIONS_MESSAGE_LOGGER.loadedDriver( driverClassName );
 		}
 		else {
 			//we're hoping that the driver is already loaded
-			CONNECTIONS_LOGGER.noDriver( AvailableSettings.DRIVER );
+			CONNECTIONS_MESSAGE_LOGGER.noDriver( AvailableSettings.DRIVER );
 			StringBuilder list = new StringBuilder();
 			Enumeration<Driver> drivers = DriverManager.getDrivers();
 			while ( drivers.hasMoreElements() ) {
@@ -143,36 +144,36 @@ public class DriverManagerConnectionProviderImpl
 				}
 				list.append( drivers.nextElement().getClass().getName() );
 			}
-			CONNECTIONS_LOGGER.loadedDrivers( list.toString() );
+			CONNECTIONS_MESSAGE_LOGGER.loadedDrivers( list.toString() );
 		}
 
 		if ( url == null ) {
-			final String msg = CONNECTIONS_LOGGER.jdbcUrlNotSpecified( AvailableSettings.URL );
+			final String msg = CONNECTIONS_MESSAGE_LOGGER.jdbcUrlNotSpecified( AvailableSettings.URL );
 			CONNECTIONS_LOGGER.error( msg );
 			throw new HibernateException( msg );
 		}
 		connectionCreatorBuilder.setUrl( url );
 
-		CONNECTIONS_LOGGER.usingUrl( url );
+		CONNECTIONS_MESSAGE_LOGGER.usingUrl( url );
 
 		final Properties connectionProps = ConnectionProviderInitiator.getConnectionProperties( configurationValues );
 
 		// if debug level is enabled, then log the password, otherwise mask it
 		if ( CONNECTIONS_LOGGER.isDebugEnabled() ) {
-			CONNECTIONS_LOGGER.connectionProperties( connectionProps );
+			CONNECTIONS_MESSAGE_LOGGER.connectionProperties( connectionProps );
 		}
 		else {
-			CONNECTIONS_LOGGER.connectionProperties( ConfigurationHelper.maskOut( connectionProps, "password" ) );
+			CONNECTIONS_MESSAGE_LOGGER.connectionProperties( ConfigurationHelper.maskOut( connectionProps, "password" ) );
 		}
 		connectionCreatorBuilder.setConnectionProps( connectionProps );
 
 		final boolean autoCommit = ConfigurationHelper.getBoolean( AvailableSettings.AUTOCOMMIT, configurationValues, false );
-		CONNECTIONS_LOGGER.autoCommitMode( autoCommit );
+		CONNECTIONS_MESSAGE_LOGGER.autoCommitMode( autoCommit );
 		connectionCreatorBuilder.setAutoCommit( autoCommit );
 
 		final Integer isolation = ConnectionProviderInitiator.extractIsolation( configurationValues );
 		if ( isolation != null ) {
-			CONNECTIONS_LOGGER.jdbcIsolationLevel( ConnectionProviderInitiator.toIsolationNiceName( isolation ) );
+			CONNECTIONS_MESSAGE_LOGGER.jdbcIsolationLevel( ConnectionProviderInitiator.toIsolationNiceName( isolation ) );
 		}
 		connectionCreatorBuilder.setIsolation( isolation );
 
@@ -284,7 +285,7 @@ public class DriverManagerConnectionProviderImpl
 			autoCommit = builder.autoCommit;
 			maxSize = builder.maxSize;
 			minSize = builder.minSize;
-			CONNECTIONS_LOGGER.hibernateConnectionPoolSize( maxSize, minSize );
+			CONNECTIONS_MESSAGE_LOGGER.hibernateConnectionPoolSize( maxSize, minSize );
 			addConnections( builder.initialSize );
 		}
 
@@ -359,7 +360,7 @@ public class DriverManagerConnectionProviderImpl
 					allConnections.remove( connection );
 				}
 				catch (SQLException e) {
-					CONNECTIONS_LOGGER.unableToCloseConnection( e );
+					CONNECTIONS_MESSAGE_LOGGER.unableToCloseConnection( e );
 				}
 			}
 		}
@@ -453,7 +454,7 @@ public class DriverManagerConnectionProviderImpl
 				if ( !active ) {
 					return;
 				}
-				CONNECTIONS_LOGGER.cleaningUpConnectionPool( pool.getUrl() );
+				CONNECTIONS_MESSAGE_LOGGER.cleaningUpConnectionPool( pool.getUrl() );
 				active = false;
 				if ( executorService != null ) {
 					executorService.shutdown();
@@ -463,7 +464,7 @@ public class DriverManagerConnectionProviderImpl
 					pool.close();
 				}
 				catch (SQLException e) {
-					CONNECTIONS_LOGGER.unableToClosePooledConnection( e );
+					CONNECTIONS_MESSAGE_LOGGER.unableToClosePooledConnection( e );
 				}
 			}
 			finally {

hibernate-core/src/main/java/org/hibernate/internal/log/ConnectionPoolingLogger.java

@@ -27,13 +27,13 @@ import static org.jboss.logging.Logger.Level.WARN;
 @MessageLogger( projectCode = "HHH" )
 @ValidIdRange( min = 10001001, max = 10001500 )
 public interface ConnectionPoolingLogger extends BasicLogger {
+	String LOGGER_NAME = "org.hibernate.orm.connections.pooling";
+
 	/**
 	 * Static access to the logging instance
 	 */
-	ConnectionPoolingLogger CONNECTIONS_LOGGER = Logger.getMessageLogger(
+	Logger CONNECTIONS_LOGGER = Logger.getLogger( LOGGER_NAME );
-			ConnectionPoolingLogger.class,
+	ConnectionPoolingLogger CONNECTIONS_MESSAGE_LOGGER = Logger.getMessageLogger( ConnectionPoolingLogger.class, LOGGER_NAME );
-			"org.hibernate.orm.connections.pooling"
-	);
 
 	@LogMessage(level = INFO)
 	@Message(value = "Connection properties: %s", id = 10001001)

hibernate-core/src/main/java/org/hibernate/internal/log/UrlMessageBundle.java

@@ -28,10 +28,13 @@ import static org.jboss.logging.Logger.Level.WARN;
 @MessageLogger( projectCode = "HHH" )
 @ValidIdRange( min = 10000001, max = 10001000 )
 public interface UrlMessageBundle {
-	public static final UrlMessageBundle URL_LOGGER = Logger.getMessageLogger(
+	String LOGGER_NAME = "org.hibernate.orm.url";
-			UrlMessageBundle.class,
+
-			"org.hibernate.orm.url"
+	Logger URL_LOGGER = Logger.getLogger( LOGGER_NAME );
-	);
+	UrlMessageBundle URL_MESSAGE_LOGGER = Logger.getMessageLogger( UrlMessageBundle.class, LOGGER_NAME );
+
+	boolean DEBUG_ENABLED = URL_LOGGER.isDebugEnabled();
+	boolean TRACE_ENABLED = URL_LOGGER.isTraceEnabled();
 
 	/**
 	 * Logs a warning about a malformed URL, caused by a {@link java.net.URISyntaxException}

hibernate-core/src/main/java/org/hibernate/loader/entity/CacheEntityLoaderHelper.java

@@ -38,6 +38,7 @@ import org.hibernate.internal.FastSessionServices;
 import org.hibernate.persister.entity.EntityPersister;
 import org.hibernate.pretty.MessageHelper;
 import org.hibernate.proxy.HibernateProxy;
+import org.hibernate.sql.results.LoadingLogger;
 import org.hibernate.stat.internal.StatsHelper;
 import org.hibernate.stat.spi.StatisticsImplementor;
 import org.hibernate.type.Type;
@@ -94,7 +95,7 @@ public class CacheEntityLoaderHelper extends AbstractLockUpgradeEventListener {
 			if ( options.isCheckDeleted() ) {
 				Status status = oldEntry.getStatus();
 				if ( status == Status.DELETED || status == Status.GONE ) {
-					LOG.debug(
+					LoadingLogger.LOGGER.debug(
 							"Load request found matching entity in context, but it is scheduled for removal; returning null" );
 					return new PersistenceContextEntry( old, EntityStatus.REMOVED_ENTITY_MARKER );
 				}

hibernate-core/src/main/java/org/hibernate/metamodel/mapping/internal/BasicValuedCollectionPart.java

@@ -179,7 +179,7 @@ public class BasicValuedCollectionPart implements CollectionPart, BasicValuedMod
 			LockMode lockMode,
 			String resultVariable,
 			DomainResultCreationState creationState) {
-		ResultsLogger.INSTANCE.debugf(
+		ResultsLogger.LOGGER.debugf(
 				"Generating Fetch for collection-part : `%s` -> `%s`",
 				collectionDescriptor.getRole(),
 				nature.getName()

hibernate-core/src/main/java/org/hibernate/resource/beans/container/spi/AbstractCdiBeanContainer.java

@@ -141,7 +141,7 @@ public abstract class AbstractCdiBeanContainer implements CdiBasedBeanContainer
 
 	@Override
 	public final void stop() {
-		BeansMessageLogger.BEANS_LOGGER.stoppingBeanContainer( this );
+		BeansMessageLogger.BEANS_MESSAGE_LOGGER.stoppingBeanContainer( this );
 		forEachBean( ContainedBeanImplementor::release );
 		registeredBeans.clear();
 		beanCache.clear();

hibernate-core/src/main/java/org/hibernate/resource/beans/internal/BeansMessageLogger.java

@@ -24,13 +24,13 @@ import static org.jboss.logging.Logger.Level.WARN;
 @MessageLogger( projectCode = "HHH" )
 @ValidIdRange( min = 10005001, max = 10010000 )
 public interface BeansMessageLogger {
+	String LOGGER_NAME = "org.hibernate.orm.beans";
+
 	/**
-	 * *The* BeansMessageLogger instance
+	 * The BeansMessageLogger instance
 	 */
-	BeansMessageLogger BEANS_LOGGER = Logger.getMessageLogger(
+	Logger BEANS_LOGGER = Logger.getLogger( LOGGER_NAME );
-			BeansMessageLogger.class,
+	BeansMessageLogger BEANS_MESSAGE_LOGGER = Logger.getMessageLogger( BeansMessageLogger.class, LOGGER_NAME );
-			"org.hibernate.orm.beans"
-	);
 
 	@LogMessage( level = WARN )
 	@Message(

hibernate-core/src/main/java/org/hibernate/resource/beans/spi/ManagedBeanRegistryInitiator.java

@@ -63,14 +63,14 @@ public class ManagedBeanRegistryInitiator implements StandardServiceInitiator<Ma
 		final Object beanManagerRef = cfgSvc.getSettings().get( AvailableSettings.CDI_BEAN_MANAGER );
 		if ( beanManagerRef != null ) {
 			if ( !isCdiAvailable ) {
-				BeansMessageLogger.BEANS_LOGGER.beanManagerButCdiNotAvailable( beanManagerRef );
+				BeansMessageLogger.BEANS_MESSAGE_LOGGER.beanManagerButCdiNotAvailable( beanManagerRef );
 			}
 
 			return CdiBeanContainerBuilder.fromBeanManagerReference( beanManagerRef, serviceRegistry );
 		}
 		else {
 			if ( isCdiAvailable ) {
-				BeansMessageLogger.BEANS_LOGGER.noBeanManagerButCdiAvailable();
+				BeansMessageLogger.BEANS_MESSAGE_LOGGER.noBeanManagerButCdiAvailable();
 			}
 		}
 

hibernate-core/src/main/java/org/hibernate/sql/results/LoadingLogger.java

@@ -0,0 +1,35 @@
+/*
+ * Hibernate, Relational Persistence for Idiomatic Java
+ *
+ * License: GNU Lesser General Public License (LGPL), version 2.1 or later
+ * See the lgpl.txt file in the root directory or http://www.gnu.org/licenses/lgpl-2.1.html
+ */
+package org.hibernate.sql.results;
+
+import org.jboss.logging.BasicLogger;
+import org.jboss.logging.Logger;
+import org.jboss.logging.annotations.MessageLogger;
+import org.jboss.logging.annotations.ValidIdRange;
+
+/**
+ * @author Steve Ebersole
+ */
+@MessageLogger( projectCode = "HHH" )
+@ValidIdRange( min = 90005801, max = 90005900 )
+public interface LoadingLogger extends BasicLogger {
+	String LOGGER_NAME = ResultsLogger.subLoggerName( "loading" );
+
+	Logger LOGGER = Logger.getLogger( LOGGER_NAME );
+	LoadingLogger MESSAGE_LOGGER = Logger.getMessageLogger( LoadingLogger.class, LOGGER_NAME );
+
+	static String subLoggerName(String subName) {
+		return LOGGER_NAME + "." + subName;
+	}
+
+	static Logger subLogger(String subName) {
+		return Logger.getLogger( subLoggerName( subName ) );
+	}
+
+	boolean TRACE_ENABLED = LOGGER.isTraceEnabled();
+	boolean DEBUG_ENABLED = LOGGER.isDebugEnabled();
+}

hibernate-core/src/main/java/org/hibernate/sql/results/ResultsLogger.java

@@ -30,14 +30,22 @@ public interface ResultsLogger extends BasicLogger {
 	/**
 	 * Static access to the logging instance
 	 */
-	ResultsLogger INSTANCE = Logger.getMessageLogger(
+	ResultsLogger LOGGER = Logger.getMessageLogger(
 			ResultsLogger.class,
 			LOGGER_NAME
 	);
 
+	static String subLoggerName(String subName) {
+		return LOGGER_NAME + "." + subName;
+	}
+
+	static Logger subLogger(String subName) {
+		return Logger.getLogger( subLoggerName( subName ) );
+	}
+
 	// todo (6.0) : make sure sql result processing classes use this logger
 
-	boolean TRACE_ENABLED = INSTANCE.isTraceEnabled();
+	boolean TRACE_ENABLED = LOGGER.isTraceEnabled();
-	boolean DEBUG_ENABLED = INSTANCE.isDebugEnabled();
+	boolean DEBUG_ENABLED = LOGGER.isDebugEnabled();
-	boolean INFO_ENABLED = INSTANCE.isInfoEnabled();
+	boolean INFO_ENABLED = LOGGER.isInfoEnabled();
 }

hibernate-core/src/main/java/org/hibernate/sql/results/graph/basic/BasicResultAssembler.java

@@ -58,7 +58,7 @@ public class BasicResultAssembler<J> implements DomainResultAssembler<J> {
 			JdbcValuesSourceProcessingOptions options) {
 		final Object jdbcValue = extractRawValue( rowProcessingState );
 
-		ResultsLogger.INSTANCE.debugf( "Extracted JDBC value [%d] - [%s]", valuesArrayPosition, jdbcValue );
+		ResultsLogger.LOGGER.debugf( "Extracted JDBC value [%d] - [%s]", valuesArrayPosition, jdbcValue );
 
 		if ( valueConverter != null ) {
 			if ( jdbcValue != null ) {

hibernate-core/src/main/java/org/hibernate/sql/results/internal/Helper.java

@@ -50,12 +50,12 @@ public class Helper {
 
 	private static Consumer<Initializer> getInitializerConsumer(List<Initializer> initializers) {
 		return initializer -> {
-			ResultsLogger.INSTANCE.debugf( "Initializer registration : %s", initializer );
+			ResultsLogger.LOGGER.debugf( "Initializer registration : %s", initializer );
 			if ( initializers.contains( initializer ) ) {
-				ResultsLogger.INSTANCE.debug( "Skipping initializer registration - already registered" );
+				ResultsLogger.LOGGER.debug( "Skipping initializer registration - already registered" );
 			}
 
-			ResultsLogger.INSTANCE.debugf( "Adding initializer : %s", initializer );
+			ResultsLogger.LOGGER.debugf( "Adding initializer : %s", initializer );
 			initializers.add( initializer );
 		};
 	}

hibernate-core/src/main/java/org/hibernate/sql/results/internal/StandardRowReader.java

@@ -11,6 +11,7 @@ import java.util.List;
 import org.hibernate.engine.spi.SessionFactoryImplementor;
 import org.hibernate.query.named.RowReaderMemento;
 import org.hibernate.sql.exec.spi.Callback;
+import org.hibernate.sql.results.LoadingLogger;
 import org.hibernate.sql.results.graph.DomainResultAssembler;
 import org.hibernate.sql.results.graph.Initializer;
 import org.hibernate.sql.results.graph.collection.CollectionInitializer;
@@ -20,15 +21,11 @@ import org.hibernate.sql.results.jdbc.spi.RowProcessingState;
 import org.hibernate.sql.results.spi.RowReader;
 import org.hibernate.sql.results.spi.RowTransformer;
 
-import org.jboss.logging.Logger;
-
 /**
  * @author Steve Ebersole
  */
 @SuppressWarnings("rawtypes")
 public class StandardRowReader<T> implements RowReader<T> {
-	private static final Logger LOG = Logger.getLogger( StandardRowReader.class );
-
 	private final List<DomainResultAssembler> resultAssemblers;
 	private final List<Initializer> initializers;
 	private final RowTransformer<T> rowTransformer;
@@ -49,6 +46,20 @@ public class StandardRowReader<T> implements RowReader<T> {
 
 		this.assemblerCount = resultAssemblers.size();
 		this.callback = callback;
+
+		logDebugInfo();
+	}
+
+	protected void logDebugInfo() {
+		// we'd really need some form of description for the assemblers and initializers for this
+		// to be useful.
+		//
+		// todo (6.0) : consider whether this ^^ is worth it
+
+//		if ( ! ResultsLogger.DEBUG_ENABLED ) {
+//			return;
+//		}
+
 	}
 
 	@Override
@@ -68,14 +79,16 @@ public class StandardRowReader<T> implements RowReader<T> {
 
 	@Override
 	public T readRow(RowProcessingState rowProcessingState, JdbcValuesSourceProcessingOptions options) {
-		LOG.debug( "---Processing Row---" );
+		LoadingLogger.LOGGER.trace( "StandardRowReader#readRow" );
 
 		coordinateInitializers( rowProcessingState, options );
 
 		final Object[] resultRow = new Object[ assemblerCount ];
 
 		for ( int i = 0; i < assemblerCount; i++ ) {
-			resultRow[i] = resultAssemblers.get( i ).assemble( rowProcessingState, options );
+			final DomainResultAssembler assembler = resultAssemblers.get( i );
+			LoadingLogger.LOGGER.debugf( "Calling top-level assembler (%i / %i) : %s", i, assemblerCount, assembler );
+			resultRow[i] = assembler.assemble( rowProcessingState, options );
 		}
 
 		afterRow( rowProcessingState, options );
@@ -84,7 +97,12 @@ public class StandardRowReader<T> implements RowReader<T> {
 	}
 
 	private void afterRow(RowProcessingState rowProcessingState, JdbcValuesSourceProcessingOptions options) {
+		LoadingLogger.LOGGER.trace( "StandardRowReader#afterRow" );
+
 		// todo (6.0) : add AfterLoadActions handling here via Callback
+		//
+		// maybe :
+		// 		initializer.finishUpRow( rowProcessingState, callback );
 
 		for ( Initializer initializer : initializers ) {
 			initializer.finishUpRow( rowProcessingState );

hibernate-core/src/main/java/org/hibernate/sql/results/jdbc/internal/JdbcValuesCacheHit.java

@@ -59,7 +59,7 @@ public class JdbcValuesCacheHit extends AbstractJdbcValues {
 
 	@Override
 	protected boolean processNext(RowProcessingState rowProcessingState) {
-		ResultsLogger.INSTANCE.tracef( "JdbcValuesCacheHit#processNext : position = %i; numberOfRows = %i", position, numberOfRows );
+		ResultsLogger.LOGGER.tracef( "JdbcValuesCacheHit#processNext : position = %i; numberOfRows = %i", position, numberOfRows );
 
 		// NOTE : explicitly skipping limit handling because the cached state ought
 		// 		already be the limited size since the cache key includes limits