HHH-19491 Improve trace logs to reduce the effort while troubleshooting issues with dirty entities

hibernate-core/src/main/java/org/hibernate/event/internal/AbstractSaveEventListener.java

@@ -412,7 +412,7 @@ protected boolean visitCollectionsBeforeSave(
 			EventSource source) {
 		final WrapVisitor visitor = new WrapVisitor( entity, id, source );
 		// substitutes into values by side effect
-		visitor.processEntityPropertyValues( values, types );
+		visitor.processEntityPropertyValues( entity, values, types );
 		return visitor.isSubstitutionRequired();
 	}
 

hibernate-core/src/main/java/org/hibernate/event/internal/AbstractVisitor.java

@@ -7,6 +7,8 @@
 import org.hibernate.HibernateException;
 import org.hibernate.bytecode.enhance.spi.LazyPropertyInitializer;
 import org.hibernate.event.spi.EventSource;
+import org.hibernate.internal.CoreLogging;
+import org.hibernate.internal.CoreMessageLogger;
 import org.hibernate.persister.entity.EntityPersister;
 import org.hibernate.type.AnyType;
 import org.hibernate.type.CollectionType;
@@ -25,6 +27,8 @@
  */
 public abstract class AbstractVisitor {
 
+	private static final CoreMessageLogger LOG = CoreLogging.messageLogger( AbstractVisitor.class );
+
 	private final EventSource session;
 
 	AbstractVisitor(EventSource session) {
@@ -35,10 +39,10 @@
 	 * Dispatch each property value to processValue().
 	 *
 	 */
-	void processValues(Object[] values, Type[] types) throws HibernateException {
+	void processValues(Object entity, Object[] values, Type[] types) throws HibernateException {
 		for ( int i=0; i<types.length; i++ ) {
 			if ( includeProperty(values, i) ) {
-				processValue( i, values, types );
+				processValue( entity, i, values, types );
 			}
 		}
 	}
@@ -47,16 +51,20 @@
 	 * Dispatch each property value to processValue().
 	 *
 	 */
-	public void processEntityPropertyValues(Object[] values, Type[] types) throws HibernateException {
+	public void processEntityPropertyValues(Object entity, Object[] values, Type[] types) throws HibernateException {
 		for ( int i=0; i<types.length; i++ ) {
-			if ( includeEntityProperty(values, i) ) {
-				processValue( i, values, types );
+			boolean includeEntityProperty = includeEntityProperty(values, i);
+			if (LOG.isTraceEnabled()) {
+				LOG.trace( "processEntityPropertyValues: type=" + types[i] + ", includeEntityProperty=" + includeEntityProperty );
+			}
+			if ( includeEntityProperty ) {
+				processValue( entity, i, values, types );
 			}
 		}
 	}
 
-	void processValue(int i, Object[] values, Type[] types) {
-		processValue( values[i], types[i] );
+	void processValue(Object entity, int i, Object[] values, Type[] types) {
+		processValue( entity, values[i], types[i], i );
 	}
 
 	boolean includeEntityProperty(Object[] values, int i) {
@@ -71,9 +79,9 @@
 	 * Visit a component. Dispatch each property
 	 * to processValue().
 	 */
-	Object processComponent(Object component, CompositeType componentType) throws HibernateException {
+	Object processComponent(Object entity, Object component, CompositeType componentType) throws HibernateException {
 		if ( component != null ) {
-			processValues( componentType.getPropertyValues(component, session), componentType.getSubtypes() );
+			processValues( entity, componentType.getPropertyValues(component, session), componentType.getSubtypes() );
 		}
 		return null;
 	}
@@ -82,38 +90,40 @@
 	 * Visit a property value. Dispatch to the
 	 * correct handler for the property type.
 	 */
-	final Object processValue(Object value, Type type) throws HibernateException {
+	final Object processValue(Object entity, Object value, Type type, int index) throws HibernateException {
+		Object rValue = null;
 		if ( type instanceof CollectionType collectionType ) {
 			//even process null collections
-			return processCollection( value, collectionType );
+			rValue = processCollection( entity, value, collectionType );
 		}
 		else if ( type instanceof EntityType entityType ) {
-			return processEntity( value, entityType );
+			rValue = processEntity( entity, value, entityType );
 		}
 		else if ( type instanceof ComponentType componentType ) {
-			return processComponent( value, componentType );
+			rValue = processComponent( entity, value, componentType );
 		}
 		else if ( type instanceof AnyType anyType ) {
-			return processComponent( value, anyType );
+			rValue = processComponent( entity, value, anyType );
 		}
-		else {
-			return null;
+		if (LOG.isTraceEnabled()) {
+			LOG.trace( "processValue: rValue=" + rValue + ", index=" + index + ", entity=" + entity + ", value=" + value + ", type=" + type );
 		}
+		return rValue;
 	}
 
 	/**
 	 * Walk the tree starting from the given entity.
 	 *
 	 */
 	public void process(Object object, EntityPersister persister) throws HibernateException {
-		processEntityPropertyValues( persister.getValues( object ), persister.getPropertyTypes() );
+		processEntityPropertyValues( object, persister.getValues( object ), persister.getPropertyTypes() );
 	}
 
 	/**
 	 * Visit a collection. Default superclass
 	 * implementation is a no-op.
 	 */
-	Object processCollection(Object collection, CollectionType type) throws HibernateException {
+	Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
 		return null;
 	}
 
@@ -122,7 +132,7 @@
 	 * entity. Default superclass implementation is
 	 * a no-op.
 	 */
-	Object processEntity(Object value, EntityType entityType) throws HibernateException {
+	Object processEntity(Object entity, Object value, EntityType entityType) throws HibernateException {
 		return null;
 	}
 

hibernate-core/src/main/java/org/hibernate/event/internal/DefaultFlushEntityEventListener.java

@@ -141,7 +141,15 @@ public void onFlushEntity(FlushEntityEvent event) throws HibernateException {
 
 		boolean substitute = wrapCollections( event, values );
 
-		if ( isUpdateNecessary( event, mightBeDirty ) ) {
+		if (LOG.isTraceEnabled()) {
+			// identity_hash_code is required because you can see the same entity multiple time and can cause confusion
+			LOG.trace( "Before scheduleUpdate: " + event.getEntity() + ", identity_hash_code=" + System.identityHashCode(event.getEntity()) );
+		}
+		boolean isUpdateNecessary = isUpdateNecessary( event, mightBeDirty );
+		if ( isUpdateNecessary ) {
+			if (LOG.isTraceEnabled()) {
+				LOG.trace( "Update is Necessary: " + event.getEntity() );
+			}
 			substitute = scheduleUpdate( event ) || substitute;
 		}
 
@@ -156,7 +164,7 @@ public void onFlushEntity(FlushEntityEvent event) throws HibernateException {
 			// We don't want to touch collections reachable from a deleted object
 			if ( persister.hasCollections() ) {
 				new FlushVisitor( session, entity )
-						.processEntityPropertyValues( values, persister.getPropertyTypes() );
+						.processEntityPropertyValues( event.getEntity(), values, persister.getPropertyTypes() );
 			}
 		}
 
@@ -199,7 +207,7 @@ private boolean wrapCollections(
 			// need to wrap before calling searchForDirtyCollections
 			final WrapVisitor visitor = new WrapVisitor( event.getEntity(), entry.getId(), event.getSession() );
 			// substitutes into values by side effect
-			visitor.processEntityPropertyValues( values, persister.getPropertyTypes() );
+			visitor.processEntityPropertyValues( event.getEntity(), values, persister.getPropertyTypes() );
 			return visitor.isSubstitutionRequired();
 		}
 		else {
@@ -241,8 +249,6 @@ private boolean scheduleUpdate(final FlushEntityEvent event) {
 		final EntityPersister persister = entry.getPersister();
 		final Object[] values = event.getPropertyValues();
 
-		logScheduleUpdate( entry, event.getFactory(), status, persister );
-
 		final boolean intercepted = !entry.isBeingReplicated() && handleInterception( event );
 
 		// increment the version number (if necessary)
@@ -274,6 +280,8 @@ private boolean scheduleUpdate(final FlushEntityEvent event) {
 				)
 		);
 
+		logScheduleUpdate( entry, event.getFactory(), status, persister );
+
 		return intercepted;
 	}
 
@@ -414,9 +422,15 @@ private static boolean isVersionIncrementRequired(FlushEntityEvent event, Entity
 	 * Note: this method is quite slow, avoid calling if possible!
 	 */
 	protected final boolean isUpdateNecessary(FlushEntityEvent event) throws HibernateException {
-		return !event.isDirtyCheckPossible()
+		boolean hasDirtyCollections = hasDirtyCollections( event );
+		boolean returnValue = !event.isDirtyCheckPossible()
 			|| event.hasDirtyProperties()
-			|| hasDirtyCollections( event );
+			|| hasDirtyCollections;
+		if (LOG.isTraceEnabled()) {
+			String formattedString = String.format("isUpdateNecessary: !isDirtyCheckPossible=%b, hasDirtyProperties=%b, hasDirtyCollections=%b", !event.isDirtyCheckPossible(), event.hasDirtyProperties(), hasDirtyCollections);
+			LOG.trace( formattedString );
+		}
+		return returnValue;
 	}
 
 	private boolean hasDirtyCollections(FlushEntityEvent event) {
@@ -436,14 +450,20 @@ private static boolean hasDirtyCollections(FlushEntityEvent event, EntityPersist
 		final DirtyCollectionSearchVisitor visitor =
 				new DirtyCollectionSearchVisitor( event.getEntity(), event.getSession(),
 						persister.getPropertyVersionability() );
-		visitor.processEntityPropertyValues( event.getPropertyValues(), persister.getPropertyTypes() );
+		visitor.processEntityPropertyValues( event.getEntity(), event.getPropertyValues(), persister.getPropertyTypes() );
 		return visitor.wasDirtyCollectionFound();
 	}
 
 	private boolean isCollectionDirtyCheckNecessary(EntityPersister persister, Status status) {
-		return ( status == Status.MANAGED || status == Status.READ_ONLY )
-			&& persister.isVersioned()
-			&& persister.hasCollections();
+		boolean statusCheck = ( status == Status.MANAGED || status == Status.READ_ONLY );
+		boolean isVersioned = persister.isVersioned();
+		boolean hasCollections = persister.hasCollections();
+		if (LOG.isTraceEnabled()) {
+			LOG.trace( "isCollectionDirtyCheckNecessary: statusCheck=" + statusCheck + ", isVersioned=" + isVersioned + ", hasCollections=" + hasCollections );
+		}
+		return statusCheck
+			&& isVersioned
+			&& hasCollections;
 	}
 
 	/**

hibernate-core/src/main/java/org/hibernate/event/internal/DefaultMergeEventListener.java

@@ -308,7 +308,7 @@ protected void entityIsTransient(MergeEvent event, Object id, MergeContext copyC
 		// with the final copy
 		new CollectionVisitor( copy, id, session )
 				.processEntityPropertyValues(
-						persister.getPropertyValuesToInsert( copy, getMergeMap( copyCache ), session ),
+						event.getEntity(), persister.getPropertyValuesToInsert( copy, getMergeMap( copyCache ), session ),
 						persister.getPropertyTypes()
 				);
 
@@ -343,7 +343,7 @@ private static class CollectionVisitor extends WrapVisitor {
 			super( entity, id, session );
 		}
 		@Override
-		protected Object processCollection(Object collection, CollectionType collectionType) {
+		protected Object processCollection(Object entity, Object collection, CollectionType collectionType) {
 			if ( collection instanceof PersistentCollection<?> persistentCollection ) {
 				final CollectionPersister persister =
 						getSession().getFactory().getMappingMetamodel()
@@ -357,7 +357,7 @@ protected Object processCollection(Object collection, CollectionType collectionT
 			return null;
 		}
 		@Override
-		Object processEntity(Object value, EntityType entityType) {
+		Object processEntity(Object entity, Object value, EntityType entityType) {
 			return null;
 		}
 	}

hibernate-core/src/main/java/org/hibernate/event/internal/DefaultReplicateEventListener.java

@@ -129,7 +129,7 @@ protected boolean visitCollectionsBeforeSave(
 			EventSource source) {
 		//TODO: we use two visitors here, inefficient!
 		OnReplicateVisitor visitor = new OnReplicateVisitor( source, id, entity, false );
-		visitor.processEntityPropertyValues( values, types );
+		visitor.processEntityPropertyValues( entity, values, types );
 		return super.visitCollectionsBeforeSave( entity, id, values, types, source );
 	}
 

hibernate-core/src/main/java/org/hibernate/event/internal/DirtyCollectionSearchVisitor.java

@@ -10,6 +10,8 @@
 import org.hibernate.engine.spi.PersistentAttributeInterceptor;
 import org.hibernate.engine.spi.SessionImplementor;
 import org.hibernate.event.spi.EventSource;
+import org.hibernate.internal.CoreLogging;
+import org.hibernate.internal.CoreMessageLogger;
 import org.hibernate.type.CollectionType;
 
 import static org.hibernate.engine.internal.ManagedTypeHelper.asPersistentAttributeInterceptable;
@@ -27,6 +29,8 @@
  */
 public class DirtyCollectionSearchVisitor extends AbstractVisitor {
 
+	private static final CoreMessageLogger LOG = CoreLogging.messageLogger( DirtyCollectionSearchVisitor.class );
+
 	private final EnhancementAsProxyLazinessInterceptor interceptor;
 	private final boolean[] propertyVersionability;
 	private boolean dirty;
@@ -49,7 +53,8 @@ public boolean wasDirtyCollectionFound() {
 		return dirty;
 	}
 
-	Object processCollection(Object collection, CollectionType type) throws HibernateException {
+	@Override
+	Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
 		if ( collection != null ) {
 			final SessionImplementor session = getSession();
 			if ( type.isArrayType() ) {
@@ -58,6 +63,9 @@ Object processCollection(Object collection, CollectionType type) throws Hibernat
 
 				// we need to check even if it was not initialized, because of delayed adds!
 				if ( session.getPersistenceContextInternal().getCollectionHolder( collection ).isDirty() ) {
+					if (LOG.isTraceEnabled()) {
+						LOG.trace( "collection is dirty. type.isArrayType() -> entity=" + entity + ", collection=" + collection + ", type=" + type);
+					}
 					dirty = true;
 				}
 			}
@@ -67,6 +75,9 @@ else if ( interceptor == null || interceptor.isAttributeLoaded( type.getName() )
 
 				// we need to check even if it was not initialized, because of delayed adds!
 				if ( ((PersistentCollection<?>) collection).isDirty() ) {
+					if (LOG.isTraceEnabled()) {
+						LOG.trace( "collection is dirty. interceptor == null -> entity=" + entity + ", collection=" + collection + ", type=" + type);
+					}
 					dirty = true;
 				}
 			}
@@ -76,6 +87,10 @@ else if ( interceptor == null || interceptor.isAttributeLoaded( type.getName() )
 
 	@Override
 	boolean includeEntityProperty(Object[] values, int i) {
-		return propertyVersionability[i] && super.includeEntityProperty( values, i );
+		boolean includeEntityProperty = super.includeEntityProperty( values, i );
+		if (LOG.isTraceEnabled()) {
+			LOG.trace( "includeEntityProperty: i=" + i + ", propertyVersionability=" + propertyVersionability[i] + ", includeEntityProperty=" + includeEntityProperty );
+		}
+		return propertyVersionability[i] && includeEntityProperty;
 	}
 }

hibernate-core/src/main/java/org/hibernate/event/internal/EvictVisitor.java

@@ -36,7 +36,7 @@ public EvictVisitor(EventSource session, Object owner) {
 	}
 
 	@Override
-	Object processCollection(Object collection, CollectionType type) throws HibernateException {
+	Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
 		if ( collection != null ) {
 			evictCollection( collection, type );
 		}

hibernate-core/src/main/java/org/hibernate/event/internal/OnLockVisitor.java

@@ -29,7 +29,7 @@ public OnLockVisitor(EventSource session, Object key, Object owner) {
 	}
 
 	@Override
-	public Object processCollection(Object collection, CollectionType type) throws HibernateException {
+	public Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
 		if ( collection == null ) {
 			return null;
 		}

hibernate-core/src/main/java/org/hibernate/event/internal/OnReplicateVisitor.java

@@ -32,7 +32,7 @@ public OnReplicateVisitor(EventSource session, Object key, Object owner, boolean
 	}
 
 	@Override
-	public Object processCollection(Object collection, CollectionType type) throws HibernateException {
+	public Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
 		if ( collection == CollectionType.UNFETCHED_COLLECTION ) {
 			return null;
 		}

hibernate-core/src/main/java/org/hibernate/event/internal/OnUpdateVisitor.java

@@ -27,7 +27,7 @@ public OnUpdateVisitor(EventSource session, Object key, Object owner) {
 	}
 
 	@Override
-	Object processCollection(Object collection, CollectionType type) throws HibernateException {
+	Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
 		if ( collection == CollectionType.UNFETCHED_COLLECTION ) {
 			return null;
 		}

hibernate-core/src/main/java/org/hibernate/event/internal/ProxyVisitor.java

@@ -22,7 +22,7 @@ public ProxyVisitor(EventSource session) {
 		super(session);
 	}
 
-	Object processEntity(Object value, EntityType entityType) {
+	Object processEntity(Object entity, Object value, EntityType entityType) {
 		if ( value != null ) {
 			getSession().getPersistenceContext().reassociateIfUninitializedProxy( value );
 			// if it is an initialized proxy, let cascade

hibernate-core/src/main/java/org/hibernate/event/internal/ReattachVisitor.java

@@ -55,13 +55,13 @@ final Object getOwner() {
 	 * {@inheritDoc}
 	 */
 	@Override
-	Object processComponent(Object component, CompositeType componentType) throws HibernateException {
+	Object processComponent(Object entity, Object component, CompositeType componentType) throws HibernateException {
 		final Type[] types = componentType.getSubtypes();
 		if ( component == null ) {
-			processValues( new Object[types.length], types );
+			processValues( entity, new Object[types.length], types );
 		}
 		else {
-			super.processComponent( component, componentType );
+			super.processComponent( entity, component, componentType );
 		}
 
 		return null;