Skip to content

Commit 6e258e6

Browse files
diegolovisondiegolovison
committed
HHH-19491 Improve trace logs to reduce the effort while troubleshooting issues with dirty entities
1 parent f97aa74 commit 6e258e6

13 files changed

+96
-51
lines changed

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -412,7 +412,7 @@ protected boolean visitCollectionsBeforeSave(
412412
EventSource source) {
413413
final WrapVisitor visitor = new WrapVisitor( entity, id, source );
414414
// substitutes into values by side effect
415-
visitor.processEntityPropertyValues( values, types );
415+
visitor.processEntityPropertyValues( entity, values, types );
416416
return visitor.isSubstitutionRequired();
417417
}
418418

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

Lines changed: 29 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,8 @@
77
import org.hibernate.HibernateException;
88
import org.hibernate.bytecode.enhance.spi.LazyPropertyInitializer;
99
import org.hibernate.event.spi.EventSource;
10+
import org.hibernate.internal.CoreLogging;
11+
import org.hibernate.internal.CoreMessageLogger;
1012
import org.hibernate.persister.entity.EntityPersister;
1113
import org.hibernate.type.AnyType;
1214
import org.hibernate.type.CollectionType;
@@ -25,6 +27,8 @@
2527
*/
2628
public abstract class AbstractVisitor {
2729

30+
private static final CoreMessageLogger LOG = CoreLogging.messageLogger( AbstractVisitor.class );
31+
2832
private final EventSource session;
2933

3034
AbstractVisitor(EventSource session) {
@@ -35,10 +39,10 @@ public abstract class AbstractVisitor {
3539
* Dispatch each property value to processValue().
3640
*
3741
*/
38-
void processValues(Object[] values, Type[] types) throws HibernateException {
42+
void processValues(Object entity, Object[] values, Type[] types) throws HibernateException {
3943
for ( int i=0; i<types.length; i++ ) {
4044
if ( includeProperty(values, i) ) {
41-
processValue( i, values, types );
45+
processValue( entity, i, values, types );
4246
}
4347
}
4448
}
@@ -47,16 +51,20 @@ void processValues(Object[] values, Type[] types) throws HibernateException {
4751
* Dispatch each property value to processValue().
4852
*
4953
*/
50-
public void processEntityPropertyValues(Object[] values, Type[] types) throws HibernateException {
54+
public void processEntityPropertyValues(Object entity, Object[] values, Type[] types) throws HibernateException {
5155
for ( int i=0; i<types.length; i++ ) {
52-
if ( includeEntityProperty(values, i) ) {
53-
processValue( i, values, types );
56+
boolean includeEntityProperty = includeEntityProperty(values, i);
57+
if (LOG.isTraceEnabled()) {
58+
LOG.trace( "processEntityPropertyValues: type=" + types[i] + ", includeEntityProperty=" + includeEntityProperty );
59+
}
60+
if ( includeEntityProperty ) {
61+
processValue( entity, i, values, types );
5462
}
5563
}
5664
}
5765

58-
void processValue(int i, Object[] values, Type[] types) {
59-
processValue( values[i], types[i] );
66+
void processValue(Object entity, int i, Object[] values, Type[] types) {
67+
processValue( entity, values[i], types[i], i );
6068
}
6169

6270
boolean includeEntityProperty(Object[] values, int i) {
@@ -71,9 +79,9 @@ boolean includeProperty(Object[] values, int i) {
7179
* Visit a component. Dispatch each property
7280
* to processValue().
7381
*/
74-
Object processComponent(Object component, CompositeType componentType) throws HibernateException {
82+
Object processComponent(Object entity, Object component, CompositeType componentType) throws HibernateException {
7583
if ( component != null ) {
76-
processValues( componentType.getPropertyValues(component, session), componentType.getSubtypes() );
84+
processValues( entity, componentType.getPropertyValues(component, session), componentType.getSubtypes() );
7785
}
7886
return null;
7987
}
@@ -82,38 +90,40 @@ Object processComponent(Object component, CompositeType componentType) throws Hi
8290
* Visit a property value. Dispatch to the
8391
* correct handler for the property type.
8492
*/
85-
final Object processValue(Object value, Type type) throws HibernateException {
93+
final Object processValue(Object entity, Object value, Type type, int index) throws HibernateException {
94+
Object rValue = null;
8695
if ( type instanceof CollectionType collectionType ) {
8796
//even process null collections
88-
return processCollection( value, collectionType );
97+
rValue = processCollection( entity, value, collectionType );
8998
}
9099
else if ( type instanceof EntityType entityType ) {
91-
return processEntity( value, entityType );
100+
rValue = processEntity( entity, value, entityType );
92101
}
93102
else if ( type instanceof ComponentType componentType ) {
94-
return processComponent( value, componentType );
103+
rValue = processComponent( entity, value, componentType );
95104
}
96105
else if ( type instanceof AnyType anyType ) {
97-
return processComponent( value, anyType );
106+
rValue = processComponent( entity, value, anyType );
98107
}
99-
else {
100-
return null;
108+
if (LOG.isTraceEnabled()) {
109+
LOG.trace( "processValue: rValue=" + rValue + ", index=" + index + ", entity=" + entity + ", value=" + value + ", type=" + type );
101110
}
111+
return rValue;
102112
}
103113

104114
/**
105115
* Walk the tree starting from the given entity.
106116
*
107117
*/
108118
public void process(Object object, EntityPersister persister) throws HibernateException {
109-
processEntityPropertyValues( persister.getValues( object ), persister.getPropertyTypes() );
119+
processEntityPropertyValues( object, persister.getValues( object ), persister.getPropertyTypes() );
110120
}
111121

112122
/**
113123
* Visit a collection. Default superclass
114124
* implementation is a no-op.
115125
*/
116-
Object processCollection(Object collection, CollectionType type) throws HibernateException {
126+
Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
117127
return null;
118128
}
119129

@@ -122,7 +132,7 @@ Object processCollection(Object collection, CollectionType type) throws Hibernat
122132
* entity. Default superclass implementation is
123133
* a no-op.
124134
*/
125-
Object processEntity(Object value, EntityType entityType) throws HibernateException {
135+
Object processEntity(Object entity, Object value, EntityType entityType) throws HibernateException {
126136
return null;
127137
}
128138

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

Lines changed: 31 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -141,7 +141,15 @@ public void onFlushEntity(FlushEntityEvent event) throws HibernateException {
141141

142142
boolean substitute = wrapCollections( event, values );
143143

144-
if ( isUpdateNecessary( event, mightBeDirty ) ) {
144+
if (LOG.isTraceEnabled()) {
145+
// identity_hash_code is required because you can see the same entity multiple time and can cause confusion
146+
LOG.trace( "Before scheduleUpdate: " + event.getEntity() + ", identity_hash_code=" + System.identityHashCode(event.getEntity()) );
147+
}
148+
boolean isUpdateNecessary = isUpdateNecessary( event, mightBeDirty );
149+
if ( isUpdateNecessary ) {
150+
if (LOG.isTraceEnabled()) {
151+
LOG.trace( "Update is Necessary: " + event.getEntity() );
152+
}
145153
substitute = scheduleUpdate( event ) || substitute;
146154
}
147155

@@ -156,7 +164,7 @@ public void onFlushEntity(FlushEntityEvent event) throws HibernateException {
156164
// We don't want to touch collections reachable from a deleted object
157165
if ( persister.hasCollections() ) {
158166
new FlushVisitor( session, entity )
159-
.processEntityPropertyValues( values, persister.getPropertyTypes() );
167+
.processEntityPropertyValues( event.getEntity(), values, persister.getPropertyTypes() );
160168
}
161169
}
162170

@@ -199,7 +207,7 @@ private boolean wrapCollections(
199207
// need to wrap before calling searchForDirtyCollections
200208
final WrapVisitor visitor = new WrapVisitor( event.getEntity(), entry.getId(), event.getSession() );
201209
// substitutes into values by side effect
202-
visitor.processEntityPropertyValues( values, persister.getPropertyTypes() );
210+
visitor.processEntityPropertyValues( event.getEntity(), values, persister.getPropertyTypes() );
203211
return visitor.isSubstitutionRequired();
204212
}
205213
else {
@@ -241,8 +249,6 @@ private boolean scheduleUpdate(final FlushEntityEvent event) {
241249
final EntityPersister persister = entry.getPersister();
242250
final Object[] values = event.getPropertyValues();
243251

244-
logScheduleUpdate( entry, event.getFactory(), status, persister );
245-
246252
final boolean intercepted = !entry.isBeingReplicated() && handleInterception( event );
247253

248254
// increment the version number (if necessary)
@@ -274,6 +280,8 @@ private boolean scheduleUpdate(final FlushEntityEvent event) {
274280
)
275281
);
276282

283+
logScheduleUpdate( entry, event.getFactory(), status, persister );
284+
277285
return intercepted;
278286
}
279287

@@ -414,9 +422,15 @@ private static boolean isVersionIncrementRequired(FlushEntityEvent event, Entity
414422
* Note: this method is quite slow, avoid calling if possible!
415423
*/
416424
protected final boolean isUpdateNecessary(FlushEntityEvent event) throws HibernateException {
417-
return !event.isDirtyCheckPossible()
425+
boolean hasDirtyCollections = hasDirtyCollections( event );
426+
boolean returnValue = !event.isDirtyCheckPossible()
418427
|| event.hasDirtyProperties()
419-
|| hasDirtyCollections( event );
428+
|| hasDirtyCollections;
429+
if (LOG.isTraceEnabled()) {
430+
String formattedString = String.format("isUpdateNecessary: !isDirtyCheckPossible=%b, hasDirtyProperties=%b, hasDirtyCollections=%b", !event.isDirtyCheckPossible(), event.hasDirtyProperties(), hasDirtyCollections);
431+
LOG.trace( formattedString );
432+
}
433+
return returnValue;
420434
}
421435

422436
private boolean hasDirtyCollections(FlushEntityEvent event) {
@@ -436,14 +450,20 @@ private static boolean hasDirtyCollections(FlushEntityEvent event, EntityPersist
436450
final DirtyCollectionSearchVisitor visitor =
437451
new DirtyCollectionSearchVisitor( event.getEntity(), event.getSession(),
438452
persister.getPropertyVersionability() );
439-
visitor.processEntityPropertyValues( event.getPropertyValues(), persister.getPropertyTypes() );
453+
visitor.processEntityPropertyValues( event.getEntity(), event.getPropertyValues(), persister.getPropertyTypes() );
440454
return visitor.wasDirtyCollectionFound();
441455
}
442456

443457
private boolean isCollectionDirtyCheckNecessary(EntityPersister persister, Status status) {
444-
return ( status == Status.MANAGED || status == Status.READ_ONLY )
445-
&& persister.isVersioned()
446-
&& persister.hasCollections();
458+
boolean statusCheck = ( status == Status.MANAGED || status == Status.READ_ONLY );
459+
boolean isVersioned = persister.isVersioned();
460+
boolean hasCollections = persister.hasCollections();
461+
if (LOG.isTraceEnabled()) {
462+
LOG.trace( "isCollectionDirtyCheckNecessary: statusCheck=" + statusCheck + ", isVersioned=" + isVersioned + ", hasCollections=" + hasCollections );
463+
}
464+
return statusCheck
465+
&& isVersioned
466+
&& hasCollections;
447467
}
448468

449469
/**

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -308,7 +308,7 @@ protected void entityIsTransient(MergeEvent event, Object id, MergeContext copyC
308308
// with the final copy
309309
new CollectionVisitor( copy, id, session )
310310
.processEntityPropertyValues(
311-
persister.getPropertyValuesToInsert( copy, getMergeMap( copyCache ), session ),
311+
event.getEntity(), persister.getPropertyValuesToInsert( copy, getMergeMap( copyCache ), session ),
312312
persister.getPropertyTypes()
313313
);
314314

@@ -343,7 +343,7 @@ private static class CollectionVisitor extends WrapVisitor {
343343
super( entity, id, session );
344344
}
345345
@Override
346-
protected Object processCollection(Object collection, CollectionType collectionType) {
346+
protected Object processCollection(Object entity, Object collection, CollectionType collectionType) {
347347
if ( collection instanceof PersistentCollection<?> persistentCollection ) {
348348
final CollectionPersister persister =
349349
getSession().getFactory().getMappingMetamodel()
@@ -357,7 +357,7 @@ protected Object processCollection(Object collection, CollectionType collectionT
357357
return null;
358358
}
359359
@Override
360-
Object processEntity(Object value, EntityType entityType) {
360+
Object processEntity(Object entity, Object value, EntityType entityType) {
361361
return null;
362362
}
363363
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -129,7 +129,7 @@ protected boolean visitCollectionsBeforeSave(
129129
EventSource source) {
130130
//TODO: we use two visitors here, inefficient!
131131
OnReplicateVisitor visitor = new OnReplicateVisitor( source, id, entity, false );
132-
visitor.processEntityPropertyValues( values, types );
132+
visitor.processEntityPropertyValues( entity, values, types );
133133
return super.visitCollectionsBeforeSave( entity, id, values, types, source );
134134
}
135135

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

Lines changed: 17 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,8 @@
1010
import org.hibernate.engine.spi.PersistentAttributeInterceptor;
1111
import org.hibernate.engine.spi.SessionImplementor;
1212
import org.hibernate.event.spi.EventSource;
13+
import org.hibernate.internal.CoreLogging;
14+
import org.hibernate.internal.CoreMessageLogger;
1315
import org.hibernate.type.CollectionType;
1416

1517
import static org.hibernate.engine.internal.ManagedTypeHelper.asPersistentAttributeInterceptable;
@@ -27,6 +29,8 @@
2729
*/
2830
public class DirtyCollectionSearchVisitor extends AbstractVisitor {
2931

32+
private static final CoreMessageLogger LOG = CoreLogging.messageLogger( DirtyCollectionSearchVisitor.class );
33+
3034
private final EnhancementAsProxyLazinessInterceptor interceptor;
3135
private final boolean[] propertyVersionability;
3236
private boolean dirty;
@@ -49,7 +53,8 @@ public boolean wasDirtyCollectionFound() {
4953
return dirty;
5054
}
5155

52-
Object processCollection(Object collection, CollectionType type) throws HibernateException {
56+
@Override
57+
Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
5358
if ( collection != null ) {
5459
final SessionImplementor session = getSession();
5560
if ( type.isArrayType() ) {
@@ -58,6 +63,9 @@ Object processCollection(Object collection, CollectionType type) throws Hibernat
5863

5964
// we need to check even if it was not initialized, because of delayed adds!
6065
if ( session.getPersistenceContextInternal().getCollectionHolder( collection ).isDirty() ) {
66+
if (LOG.isTraceEnabled()) {
67+
LOG.trace( "collection is dirty. type.isArrayType() -> entity=" + entity + ", collection=" + collection + ", type=" + type);
68+
}
6169
dirty = true;
6270
}
6371
}
@@ -67,6 +75,9 @@ else if ( interceptor == null || interceptor.isAttributeLoaded( type.getName() )
6775

6876
// we need to check even if it was not initialized, because of delayed adds!
6977
if ( ((PersistentCollection<?>) collection).isDirty() ) {
78+
if (LOG.isTraceEnabled()) {
79+
LOG.trace( "collection is dirty. interceptor == null -> entity=" + entity + ", collection=" + collection + ", type=" + type);
80+
}
7081
dirty = true;
7182
}
7283
}
@@ -76,6 +87,10 @@ else if ( interceptor == null || interceptor.isAttributeLoaded( type.getName() )
7687

7788
@Override
7889
boolean includeEntityProperty(Object[] values, int i) {
79-
return propertyVersionability[i] && super.includeEntityProperty( values, i );
90+
boolean includeEntityProperty = super.includeEntityProperty( values, i );
91+
if (LOG.isTraceEnabled()) {
92+
LOG.trace( "includeEntityProperty: i=" + i + ", propertyVersionability=" + propertyVersionability[i] + ", includeEntityProperty=" + includeEntityProperty );
93+
}
94+
return propertyVersionability[i] && includeEntityProperty;
8095
}
8196
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -36,7 +36,7 @@ public EvictVisitor(EventSource session, Object owner) {
3636
}
3737

3838
@Override
39-
Object processCollection(Object collection, CollectionType type) throws HibernateException {
39+
Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
4040
if ( collection != null ) {
4141
evictCollection( collection, type );
4242
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ public OnLockVisitor(EventSource session, Object key, Object owner) {
2929
}
3030

3131
@Override
32-
public Object processCollection(Object collection, CollectionType type) throws HibernateException {
32+
public Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
3333
if ( collection == null ) {
3434
return null;
3535
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ public OnReplicateVisitor(EventSource session, Object key, Object owner, boolean
3232
}
3333

3434
@Override
35-
public Object processCollection(Object collection, CollectionType type) throws HibernateException {
35+
public Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
3636
if ( collection == CollectionType.UNFETCHED_COLLECTION ) {
3737
return null;
3838
}

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,7 @@ public OnUpdateVisitor(EventSource session, Object key, Object owner) {
2727
}
2828

2929
@Override
30-
Object processCollection(Object collection, CollectionType type) throws HibernateException {
30+
Object processCollection(Object entity, Object collection, CollectionType type) throws HibernateException {
3131
if ( collection == CollectionType.UNFETCHED_COLLECTION ) {
3232
return null;
3333
}

0 commit comments

Comments
 (0)