HHH-19611 demote many DEBUG-level log messages to TRACE #10525

gavinking · 2025-07-13T22:00:48Z

Redo of #10520.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license
and can be relicensed under the terms of the LGPL v2.1 license in the future at the maintainers' discretion.
For more information on licensing, please check here.

since Quarkus insists on doing something completely crazy with our INFO level

put them all in a single log message

because it results in logging telling us not to do it

and clean up some Logger descriptions

…to JdbcLogging and include SF uuid in log messages

…sImpl

at least for now - it was just too verbose

at least for now - it was just too ugly and verbose

motivated by work on logging cleanup

hibernate-github-bot · 2025-07-13T22:00:59Z

Thanks for your pull request!

This pull request does not follow the contribution rules. Could you have a look?

❌ All commit messages should start with a JIRA issue key matching pattern HHH-\d+
↳ Offending commits: [74f8976, 055b4fe, 8ba81d4, a311903, 7495085, d5ec2f6, 6b9a6d3, 0e14088, e3a06c6, 5113f19, 7d2fc89, e3d89dd, 60a413c, 142b9c6, 13215a5, 6c7d383, 639a7b9, 4133366, a70ea5e, f3baef5, a9f8e4b, b78d8ef, 4e9d3a8, af4342b, 363308a, 41fcfa0, c041ec4, 4404d9c, 1c8dcc2]

› This message was automatically generated.

hibernate-core/src/main/java/org/hibernate/boot/jaxb/internal/MappingBinder.java

-			if ( log.isDebugEnabled() ) {
-				log.debugf( "Performing JAXB binding of hbm.xml document : %s", origin.toString() );
+			if ( log.isTraceEnabled() ) {
+				log.tracef( "Performing JAXB binding of hbm.xml document: %s", origin.toString() );


hibernate-core/src/main/java/org/hibernate/boot/jaxb/internal/MappingBinder.java

@@ -181,7 +181,7 @@
 		else {
 			assert "entity-mappings".equals( rootElementLocalName );
 			try {
-				log.debugf( "Performing JAXB binding of orm.xml document : %s", origin.toString() );
+				log.tracef( "Performing JAXB binding of orm.xml document: %s", origin.toString() );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

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

@@ -1015,7 +1015,7 @@
 	public Object immediateLoad(String entityName, Object id) {
 		if ( log.isDebugEnabled() ) {
 			final EntityPersister persister = requireEntityPersister( entityName );
-			log.debugf( "Initializing proxy: %s", infoString( persister, id, getFactory() ) );
+			log.tracef( "Initializing proxy: %s", infoString( persister, id, getFactory() ) );


hibernate-core/src/main/java/org/hibernate/loader/ast/internal/AbstractEntityBatchLoader.java

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

+			LOG.trace( "Caching collection: "
+					+ collectionInfoString( collectionDescriptor, collectionInstance, key, session ) );


hibernate-core/src/main/java/org/hibernate/type/BasicTypeRegistry.java

+				// Incredibly verbose logging disabled
+//				LOG.tracef( "Adding type registration %s -> %s", key, type );
+
+				final Type old = typesByName.put( key, type );


hibernate-core/src/main/java/org/hibernate/type/BasicTypeRegistry.java

+				// Incredibly verbose logging disabled
+//				LOG.tracef( "Adding type registration %s -> %s", key, type );
+
+				final BasicTypeReference<?> old = typeReferencesByName.put( key, type );


hibernate-core/src/main/java/org/hibernate/boot/jaxb/internal/XmlSources.java

@@ -38,7 +39,7 @@
 	 * Create an {@link XmlSource} from a named resource
 	 */
 	public static XmlSource fromResource(String resourceName, ClassLoaderService classLoaderService) {
-		JaxbLogger.JAXB_LOGGER.tracef( "reading mappings from resource : %s", resourceName );
+		JAXB_LOGGER.tracef( "Reading mappings from resource: %s", resourceName );


hibernate-core/src/main/java/org/hibernate/loader/ast/internal/AbstractEntityBatchLoader.java

hibernate-core/src/main/java/org/hibernate/loader/ast/internal/EntityBatchLoaderArrayParam.java

...rnate-core/src/main/java/org/hibernate/loader/ast/internal/EntityBatchLoaderInPredicate.java

...nate-core/src/main/java/org/hibernate/loader/ast/internal/AbstractCollectionBatchLoader.java

+			MULTI_KEY_LOAD_LOGGER.trace( "Batch fetching collection: "
+					+ collectionInfoString( getLoadable(), key ) );


...nate-core/src/main/java/org/hibernate/loader/ast/internal/AbstractCollectionBatchLoader.java

+			MULTI_KEY_LOAD_LOGGER.trace( "Finishing initializing batch-fetched collection: "
+					+ collectionInfoString( attributeMapping, key ) );


hibernate-core/src/main/java/org/hibernate/loader/ast/internal/AbstractEntityBatchLoader.java

+			MULTI_KEY_LOAD_LOGGER.trace( "Batch fetching entity: "
+					+ infoString( getLoadable(), id ) );


hibernate-core/src/main/java/org/hibernate/loader/ast/internal/AbstractEntityBatchLoader.java

+			MULTI_KEY_LOAD_LOGGER.trace( "Batch fetching entity: "
+					+ infoString( getLoadable(), id ) );


...te-core/src/main/java/org/hibernate/loader/ast/internal/CollectionBatchLoaderArrayParam.java

+			MULTI_KEY_LOAD_LOGGER.trace( "Batch fetching collection: "
+					+ collectionInfoString( getLoadable(), keyBeingLoaded ) );


...e-core/src/main/java/org/hibernate/loader/ast/internal/CollectionBatchLoaderInPredicate.java

-								key,
+						MULTI_KEY_LOAD_LOGGER.tracef(
+								"Processing collection batch-fetch chunk (%s) %s - %s",
+								collectionInfoString( getLoadable(), key ),


hibernate-core/src/main/java/org/hibernate/loader/ast/internal/DatabaseSnapshotExecutor.java

+			LOADER_LOGGER.trace( "Retrieving snapshot of current persistent state for "
+					+ infoString( entityDescriptor, id ) );


hibernate-core/src/main/java/org/hibernate/loader/ast/internal/EntityBatchLoaderArrayParam.java

-					getLoadable().getEntityName(), id, Arrays.toString(idsToInitialize) );
+		if ( MULTI_KEY_LOAD_LOGGER.isTraceEnabled() ) {
+			MULTI_KEY_LOAD_LOGGER.tracef( "Entity ids to initialize via batch fetching (%s) %s",
+					infoString( getLoadable(), id),


...rnate-core/src/main/java/org/hibernate/loader/ast/internal/EntityBatchLoaderInPredicate.java

-					getLoadable().getEntityName(), pkValue, Arrays.toString(idsToInitialize) );
+		if ( MULTI_KEY_LOAD_LOGGER.isTraceEnabled() ) {
+			MULTI_KEY_LOAD_LOGGER.tracef( "Entity ids to initialize via batch fetching (%s) %s",
+					infoString( getLoadable(), pkValue ),


...rnate-core/src/main/java/org/hibernate/loader/ast/internal/EntityBatchLoaderInPredicate.java

+							if ( MULTI_KEY_LOAD_LOGGER.isTraceEnabled() ) {
+								MULTI_KEY_LOAD_LOGGER.tracef(
+										"Processing entity batch-fetch chunk (%s) %s - %s",
+										infoString( getLoadable(), pkValue ),


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

+		final boolean traceEnabled = L2CACHE_LOGGER.isTraceEnabled();
+		if ( traceEnabled ) {
+			L2CACHE_LOGGER.tracef( "Getting cached data from region ['%s' (%s)] by key [%s]",
+					getRegion().getName(), getAccessType(), key );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

-					log.debugf( "Cache miss : region = `%s`, key = `%s`", getRegion().getName(), key );
+				if ( traceEnabled ) {
+					L2CACHE_LOGGER.tracef( "Cache miss: region = '%s', key = '%s'",
+							getRegion().getName(), key );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

-					log.debugf( "Cache hit : region = `%s`, key = `%s`", getRegion().getName(), key );
+				if ( traceEnabled ) {
+					L2CACHE_LOGGER.tracef( "Cache hit: region = '%s', key = '%s'",
+							getRegion().getName(), key );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

-					log.debugf( "Cache hit, but item is unreadable/invalid : region = `%s`, key = `%s`", getRegion().getName(), key );
+				if ( traceEnabled ) {
+					L2CACHE_LOGGER.tracef( "Cache hit, but item is unreadable/invalid: region = '%s', key = '%s'",
+							getRegion().getName(), key );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

+				L2CACHE_LOGGER.tracef( "Caching data from load [region='%s' (%s)] : key[%s] -> value[%s]",
+						getRegion().getName(), getAccessType(), key, value );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

+				L2CACHE_LOGGER.tracef( "Locking cache item [region='%s' (%s)] : '%s' (timeout=%s, version=%s)",
+						getRegion().getName(), getAccessType(), key, timeout, version );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

-				);
+			if ( L2CACHE_LOGGER.isTraceEnabled() ) {
+				L2CACHE_LOGGER.tracef( "Unlocking cache item [region='%s' (%s)] : %s",
+						getRegion().getName(), getAccessType(), key );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

@@ -205,7 +205,7 @@

 	protected void handleLockExpiry(SharedSessionContractImplementor session, Object key, Lockable lock) {
 		L2CACHE_LOGGER.softLockedCacheExpired( getRegion().getName(), key );
-		log.debugf( "Cached entry expired : %s", key );
+		L2CACHE_LOGGER.tracef( "Cached entry expired: %s", key );


hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java

@@ -219,7 +219,9 @@
 	@Override
 	public void remove(SharedSessionContractImplementor session, Object key) {
 		if ( getStorageAccess().getFromCache( key, session ) instanceof SoftLock ) {
-			log.debugf( "Skipping #remove call in read-write access to maintain SoftLock : %s", key );
+			if ( L2CACHE_LOGGER.isDebugEnabled() ) {
+				L2CACHE_LOGGER.debugf( "Skipping remove call in read-write access to maintain SoftLock: ", key );


gavinking · 2025-07-14T11:30:31Z

This is massive now, so I'm going to just merge it.

gavinking added 23 commits July 13, 2025 23:58

demote many DEBUG-level log messages to TRACE

74f8976

since Quarkus insists on doing something completely crazy with our INFO level

improvements to TRACE-level logging

055b4fe

change how HQL functions are logged at startup

8ba81d4

put them all in a single log message

avoid use of deprecated service lookup

a311903

because it results in logging telling us not to do it

downgrade two more DEBUG-level messages to TRACE

7495085

very minor code cleanups in ResourceRegistryStandardImpl

d5ec2f6

very minor code cleanups in ManagedTypeProcessor

6b9a6d3

introduce ResourceRegistryLogger

0e14088

and clean up some Logger descriptions

move logging in JdbcCoordinatorImpl and LogicalConnectionManagedImpl …

e3a06c6

…to JdbcLogging and include SF uuid in log messages

massive cleanup of NaturalIdResolutionsImpl

5113f19

move NaturalIdLogging to package with its only client

7d2fc89

improve logging for Services and Statistics

e3d89dd

trivial changes to logging in JndiServiceImpl

60a413c

move logging to JdbcEnvironmentInitiator to JdbcLogging

142b9c6

fix verbosity of logging in BootstrapContextImpl and ClassLoaderAcces…

13215a5

…sImpl

improve log message in StrategySelectorImpl

6c7d383

slightly improve format of log message in AttributeFactory

639a7b9

more consistent format for logging in boot.model package

4133366

remove another ugly log message from query compiler

a70ea5e

disable TRACE logging from type registries

f3baef5

at least for now - it was just too verbose

disable TRACE logging from SqmFunctionRegistry

a9f8e4b

at least for now - it was just too ugly and verbose

Big clean up around natural id stuff

b78d8ef

motivated by work on logging cleanup

minor optimizations to logging and comments in event handlers

4e9d3a8

gavinking marked this pull request as ready for review July 13, 2025 22:00

github-advanced-security bot found potential problems Jul 13, 2025

View reviewed changes

gavinking added 3 commits July 14, 2025 10:14

minor aesthetic cleanups in batch loader logging

af4342b

misc very minor consistency fixes for logging

363308a

migrate QueryResultsCacheImpl logging to SecondLevelCacheLogger

41fcfa0

github-advanced-security bot found potential problems Jul 14, 2025

View reviewed changes

gavinking added 3 commits July 14, 2025 11:16

introduce new infoString methods for batch loaders

c041ec4

fix jdoc of QueryResultsCacheImpl

4404d9c

use typesafe logging for all L2 cache stuff

1c8dcc2

github-advanced-security bot found potential problems Jul 14, 2025

View reviewed changes

gavinking added 3 commits July 14, 2025 12:56

Use L2CACHE_LOGGER from o.h.cache.spi.support

7d892c5

LazyInitializationException probably shouldn't log from its constructor

f0aa4d1

very minor cleanups

fe2893d

github-advanced-security bot found potential problems Jul 14, 2025

View reviewed changes

gavinking merged commit 05684de into hibernate:main Jul 14, 2025
22 of 23 checks passed

		LOG.trace( "Caching collection: "
		+ collectionInfoString( collectionDescriptor, collectionInstance, key, session ) );

		MULTI_KEY_LOAD_LOGGER.trace( "Batch fetching collection: "
		+ collectionInfoString( getLoadable(), key ) );

		MULTI_KEY_LOAD_LOGGER.trace( "Finishing initializing batch-fetched collection: "
		+ collectionInfoString( attributeMapping, key ) );

		MULTI_KEY_LOAD_LOGGER.trace( "Batch fetching entity: "
		+ infoString( getLoadable(), id ) );

		LOADER_LOGGER.trace( "Retrieving snapshot of current persistent state for "
		+ infoString( entityDescriptor, id ) );

		L2CACHE_LOGGER.tracef( "Caching data from load [region='%s' (%s)] : key[%s] -> value[%s]",
		getRegion().getName(), getAccessType(), key, value );

		L2CACHE_LOGGER.tracef( "Locking cache item [region='%s' (%s)] : '%s' (timeout=%s, version=%s)",
		getRegion().getName(), getAccessType(), key, timeout, version );

HHH-19611 demote many DEBUG-level log messages to TRACE #10525

HHH-19611 demote many DEBUG-level log messages to TRACE #10525

Conversation

gavinking commented Jul 13, 2025

Uh oh!

hibernate-github-bot bot commented Jul 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Check failure

Uh oh!

Uh oh!

Check failure

Uh oh!

Check notice

Check notice

Check failure

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

Check failure

Uh oh!

gavinking commented Jul 14, 2025

Uh oh!

Uh oh!

Uh oh!

hibernate-github-bot bot commented Jul 13, 2025 •

edited

Loading