get rid of use of tracev()

- at most one of these is worse without it
- there was even a performance bug due to missing isTraceEnabled()
This commit is contained in:
Gavin King 2024-12-13 00:48:10 +01:00
parent 1b1dfaecd0
commit aa6e46eb79
13 changed files with 54 additions and 105 deletions

View File

@ -160,7 +160,7 @@ public abstract class AbstractSaveEventListener<C> implements CallbackRegistryCo
if ( LOG.isDebugEnabled() ) { if ( LOG.isDebugEnabled() ) {
// TODO: define toString()s for generators // TODO: define toString()s for generators
LOG.debugf( LOG.debugf(
"Generated identifier: %s, using strategy: %s", "Generated identifier [%s] using generator '%s'",
persister.getIdentifierType().toLoggableString( id, source.getFactory() ), persister.getIdentifierType().toLoggableString( id, source.getFactory() ),
generator.getClass().getName() generator.getClass().getName()
); );
@ -210,7 +210,7 @@ public abstract class AbstractSaveEventListener<C> implements CallbackRegistryCo
} }
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Saving {0}", infoString( persister, id, source.getFactory() ) ); LOG.trace( "Saving " + infoString( persister, id, source.getFactory() ) );
} }
final EntityKey key = useIdentityColumn ? null : entityKey( id, persister, source ); final EntityKey key = useIdentityColumn ? null : entityKey( id, persister, source );

View File

@ -38,7 +38,6 @@ import org.hibernate.jpa.event.spi.CallbackType;
import org.hibernate.metamodel.spi.MappingMetamodelImplementor; import org.hibernate.metamodel.spi.MappingMetamodelImplementor;
import org.hibernate.persister.collection.CollectionPersister; import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.persister.entity.EntityPersister; import org.hibernate.persister.entity.EntityPersister;
import org.hibernate.pretty.MessageHelper;
import org.hibernate.property.access.internal.PropertyAccessStrategyBackRefImpl; import org.hibernate.property.access.internal.PropertyAccessStrategyBackRefImpl;
import org.hibernate.proxy.LazyInitializer; import org.hibernate.proxy.LazyInitializer;
import org.hibernate.type.CollectionType; import org.hibernate.type.CollectionType;
@ -47,6 +46,7 @@ import org.hibernate.type.Type;
import org.hibernate.type.TypeHelper; import org.hibernate.type.TypeHelper;
import static org.hibernate.engine.internal.Collections.skipRemoval; import static org.hibernate.engine.internal.Collections.skipRemoval;
import static org.hibernate.pretty.MessageHelper.infoString;
import static org.hibernate.proxy.HibernateProxy.extractLazyInitializer; import static org.hibernate.proxy.HibernateProxy.extractLazyInitializer;
/** /**
@ -134,8 +134,7 @@ public class DefaultDeleteEventListener implements DeleteEventListener, Callback
} }
} }
else if ( type instanceof ComponentType componentType ) { else if ( type instanceof ComponentType componentType ) {
final Type[] subtypes = componentType.getSubtypes(); for ( Type subtype : componentType.getSubtypes() ) {
for ( Type subtype : subtypes ) {
deleteOwnedCollections( subtype, key, session ); deleteOwnedCollections( subtype, key, session );
} }
} }
@ -367,10 +366,7 @@ public class DefaultDeleteEventListener implements DeleteEventListener, Callback
final DeleteContext transientEntities) { final DeleteContext transientEntities) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Deleting " + infoString( persister, entityEntry.getId(), session.getFactory() ) );
"Deleting {0}",
MessageHelper.infoString( persister, entityEntry.getId(), session.getFactory() )
);
} }
final PersistenceContext persistenceContext = session.getPersistenceContextInternal(); final PersistenceContext persistenceContext = session.getPersistenceContextInternal();

View File

@ -109,7 +109,7 @@ public class DefaultEvictEventListener implements EvictEventListener {
final EventSource session) final EventSource session)
throws HibernateException { throws HibernateException {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Evicting {0}", infoString( persister ) ); LOG.trace( "Evicting " + infoString( persister ) );
} }
final PersistenceContext persistenceContext = session.getPersistenceContextInternal(); final PersistenceContext persistenceContext = session.getPersistenceContextInternal();

View File

@ -292,31 +292,20 @@ public class DefaultFlushEntityEventListener implements FlushEntityEventListener
private static void logScheduleUpdate(EntityEntry entry, SessionFactoryImplementor factory, Status status, EntityPersister persister) { private static void logScheduleUpdate(EntityEntry entry, SessionFactoryImplementor factory, Status status, EntityPersister persister) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
final String info = infoString( persister, entry.getId(), factory );
if ( status == Status.DELETED ) { if ( status == Status.DELETED ) {
if ( !persister.isMutable() ) { if ( !persister.isMutable() ) {
LOG.tracev( LOG.trace( "Updating immutable, deleted entity: " + info );
"Updating immutable, deleted entity: {0}",
infoString(persister, entry.getId(), factory)
);
} }
else if ( !entry.isModifiableEntity() ) { else if ( !entry.isModifiableEntity() ) {
LOG.tracev( LOG.trace( "Updating non-modifiable, deleted entity: " + info );
"Updating non-modifiable, deleted entity: {0}",
infoString(persister, entry.getId(), factory)
);
} }
else { else {
LOG.tracev( LOG.trace( "Updating deleted entity: " + info );
"Updating deleted entity: {0}",
infoString(persister, entry.getId(), factory)
);
} }
} }
else { else {
LOG.tracev( LOG.trace( "Updating entity: " + info );
"Updating entity: {0}",
infoString(persister, entry.getId(), factory)
);
} }
} }
} }
@ -681,11 +670,10 @@ public class DefaultFlushEntityEventListener implements FlushEntityEventListener
for ( int i = 0; i < dirtyProperties.length; i++ ) { for ( int i = 0; i < dirtyProperties.length; i++ ) {
dirtyPropertyNames[i] = allPropertyNames[dirtyProperties[i]]; dirtyPropertyNames[i] = allPropertyNames[dirtyProperties[i]];
} }
LOG.tracev( if ( LOG.isTraceEnabled() ) {
"Found dirty properties [{0}] : {1}", LOG.trace( "Found dirty properties [" + infoString( persister.getEntityName(), entry.getId() )
infoString( persister.getEntityName(), entry.getId() ), + "] : "+ Arrays.toString( dirtyPropertyNames ) );
Arrays.toString( dirtyPropertyNames ) }
);
} }
} }

View File

@ -47,10 +47,8 @@ public class DefaultInitializeCollectionEventListener implements InitializeColle
final CollectionPersister loadedPersister = ce.getLoadedPersister(); final CollectionPersister loadedPersister = ce.getLoadedPersister();
final Object loadedKey = ce.getLoadedKey(); final Object loadedKey = ce.getLoadedKey();
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Initializing collection "
"Initializing collection {0}", + collectionInfoString( loadedPersister, collection, loadedKey, source ) );
collectionInfoString( loadedPersister, collection, loadedKey, source )
);
LOG.trace( "Checking second-level cache" ); LOG.trace( "Checking second-level cache" );
} }

View File

@ -226,10 +226,7 @@ public class DefaultLoadEventListener implements LoadEventListener {
*/ */
private Object proxyOrLoad(LoadEvent event, EntityPersister persister, EntityKey keyToLoad, LoadType options) { private Object proxyOrLoad(LoadEvent event, EntityPersister persister, EntityKey keyToLoad, LoadType options) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Loading entity: " + infoString( persister, event.getEntityId(), persister.getFactory() ) );
"Loading entity: {0}",
infoString( persister, event.getEntityId(), persister.getFactory() )
);
} }
if ( hasBytecodeProxy( persister, options ) ) { if ( hasBytecodeProxy( persister, options ) ) {
return loadWithBytecodeProxy( event, persister, keyToLoad, options ); return loadWithBytecodeProxy( event, persister, keyToLoad, options );
@ -515,10 +512,7 @@ public class DefaultLoadEventListener implements LoadEventListener {
final EventSource session = event.getSession(); final EventSource session = event.getSession();
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Attempting to resolve: " + infoString( persister, event.getEntityId(), event.getFactory() ) );
"Attempting to resolve: {0}",
infoString( persister, event.getEntityId(), event.getFactory() )
);
} }
if ( session.getPersistenceContextInternal().containsDeletedUnloadedEntityKey( keyToLoad ) ) { if ( session.getPersistenceContextInternal().containsDeletedUnloadedEntityKey( keyToLoad ) ) {
@ -547,8 +541,8 @@ public class DefaultLoadEventListener implements LoadEventListener {
if ( isPersistentAttributeInterceptable( entity ) ) { if ( isPersistentAttributeInterceptable( entity ) ) {
final PersistentAttributeInterceptable interceptable = asPersistentAttributeInterceptable( entity ); final PersistentAttributeInterceptable interceptable = asPersistentAttributeInterceptable( entity );
final PersistentAttributeInterceptor interceptor = interceptable.$$_hibernate_getInterceptor(); final PersistentAttributeInterceptor interceptor = interceptable.$$_hibernate_getInterceptor();
if ( interceptor instanceof EnhancementAsProxyLazinessInterceptor ) { if ( interceptor instanceof EnhancementAsProxyLazinessInterceptor lazinessInterceptor ) {
( (EnhancementAsProxyLazinessInterceptor) interceptor ).forceInitialize( entity, null ); lazinessInterceptor.forceInitialize( entity, null );
} }
} }
} }
@ -568,23 +562,15 @@ public class DefaultLoadEventListener implements LoadEventListener {
private Object loadFromCacheOrDatasource(LoadEvent event, EntityPersister persister, EntityKey keyToLoad) { private Object loadFromCacheOrDatasource(LoadEvent event, EntityPersister persister, EntityKey keyToLoad) {
final Object entity = CacheEntityLoaderHelper.INSTANCE.loadFromSecondLevelCache( event, persister, keyToLoad ); final Object entity = CacheEntityLoaderHelper.INSTANCE.loadFromSecondLevelCache( event, persister, keyToLoad );
if ( entity != null ) { if ( entity == null ) {
if ( LOG.isTraceEnabled() ) { return loadFromDatasource( event, persister );
LOG.tracev(
"Resolved object in second-level cache: {0}",
infoString( persister, event.getEntityId(), event.getFactory() )
);
}
return entity;
} }
else { else {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Resolved entity in second-level cache: "
"Object not resolved in any cache: {0}", + infoString( persister, event.getEntityId(), event.getFactory() ) );
infoString( persister, event.getEntityId(), event.getFactory() )
);
} }
return loadFromDatasource( event, persister ); return entity;
} }
} }
@ -598,6 +584,11 @@ public class DefaultLoadEventListener implements LoadEventListener {
* @return The object loaded from the datasource, or null if not found. * @return The object loaded from the datasource, or null if not found.
*/ */
protected Object loadFromDatasource(final LoadEvent event, final EntityPersister persister) { protected Object loadFromDatasource(final LoadEvent event, final EntityPersister persister) {
if ( LOG.isTraceEnabled() ) {
LOG.trace( "Entity not resolved in any cache, loading from datastore: "
+ infoString( persister, event.getEntityId(), event.getFactory() ) );
}
Object entity = persister.load( Object entity = persister.load(
event.getEntityId(), event.getEntityId(),
event.getInstanceToLoad(), event.getInstanceToLoad(),

View File

@ -120,10 +120,7 @@ public class DefaultLockEventListener implements LockEventListener {
protected final EntityEntry reassociate(AbstractEvent event, Object object, Object id, EntityPersister persister) { protected final EntityEntry reassociate(AbstractEvent event, Object object, Object id, EntityPersister persister) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Reassociating transient instance: " + infoString( persister, id, event.getFactory() ) );
"Reassociating transient instance: {0}",
infoString( persister, id, event.getFactory() )
);
} }
final EventSource source = event.getSession(); final EventSource source = event.getSession();

View File

@ -132,10 +132,7 @@ public class DefaultRefreshEventListener implements RefreshEventListener {
+ "' because it has a null identifier" ); + "' because it has a null identifier" );
} }
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Refreshing transient " + infoString( persister, id, event.getFactory() ) );
"Refreshing transient {0}",
infoString( persister, id, event.getFactory() )
);
} }
if ( persistenceContext.getEntry( source.generateEntityKey( id, persister ) ) != null ) { if ( persistenceContext.getEntry( source.generateEntityKey( id, persister ) ) != null ) {
throw new NonUniqueObjectException( id, persister.getEntityName() ); throw new NonUniqueObjectException( id, persister.getEntityName() );
@ -143,10 +140,7 @@ public class DefaultRefreshEventListener implements RefreshEventListener {
} }
else { else {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Refreshing " + infoString( entry.getPersister(), entry.getId(), event.getFactory() ) );
"Refreshing ",
infoString( entry.getPersister(), entry.getId(), event.getFactory() )
);
} }
if ( !entry.isExistsInDatabase() ) { if ( !entry.isExistsInDatabase() ) {
throw new UnresolvableObjectException( throw new UnresolvableObjectException(

View File

@ -85,8 +85,7 @@ public class DefaultReplicateEventListener
if ( oldVersion != null ) { if ( oldVersion != null ) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev("Found existing row for {0}", LOG.trace( "Found existing row for " + infoString( persister, id, event.getFactory() ) );
infoString( persister, id, event.getFactory() ) );
} }
// If the entity has no version, getCurrentVersion() just returns // If the entity has no version, getCurrentVersion() just returns
// a meaningless value to indicate that the row exists (HHH-2378) // a meaningless value to indicate that the row exists (HHH-2378)
@ -107,8 +106,8 @@ public class DefaultReplicateEventListener
else { else {
// no existing row - execute a SQL INSERT // no existing row - execute a SQL INSERT
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "No existing row, replicating new instance {0}", LOG.trace( "No existing row, replicating new instance "
infoString( persister, id, event.getFactory() ) ); + infoString( persister, id, event.getFactory() ) );
} }
final boolean regenerate = persister.isIdentifierAssignedByInsert(); // prefer re-generation of identity! final boolean regenerate = persister.isIdentifierAssignedByInsert(); // prefer re-generation of identity!
final EntityKey key = regenerate ? null : source.generateEntityKey( id, persister ); final EntityKey key = regenerate ? null : source.generateEntityKey( id, persister );
@ -158,8 +157,7 @@ public class DefaultReplicateEventListener
EventSource source) throws HibernateException { EventSource source) throws HibernateException {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Replicating changes to {0}", LOG.trace( "Replicating changes to " + infoString( persister, id, source.getFactory() ) );
infoString( persister, id, source.getFactory() ) );
} }
new OnReplicateVisitor( source, id, entity, true ).process( entity, persister ); new OnReplicateVisitor( source, id, entity, true ).process( entity, persister );

View File

@ -48,34 +48,22 @@ public class DefaultResolveNaturalIdEventListener implements ResolveNaturalIdEve
final EntityPersister persister = event.getEntityPersister(); final EntityPersister persister = event.getEntityPersister();
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Attempting to resolve: " + infoString( persister ) + "#" + event.getNaturalIdValues() );
"Attempting to resolve: {0}#{1}",
infoString( persister ),
event.getNaturalIdValues()
);
} }
final Object entityId = resolveFromCache( event ); final Object entityId = resolveFromCache( event );
if ( entityId != null ) { if ( entityId != null ) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Resolved object in cache: " + infoString( persister ) + "#" + event.getNaturalIdValues() );
"Resolved object in cache: {0}#{1}",
infoString( persister ),
event.getNaturalIdValues()
);
} }
return entityId; return entityId;
} }
else {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Object not resolved in any cache: "+ infoString( persister ) + "#" + event.getNaturalIdValues() );
"Object not resolved in any cache: {0}#{1}", }
infoString( persister ), return loadFromDatasource( event );
event.getNaturalIdValues()
);
} }
return loadFromDatasource( event );
} }
/** /**

View File

@ -44,13 +44,13 @@ public enum EntityState {
if ( entry.getStatus() != Status.DELETED ) { if ( entry.getStatus() != Status.DELETED ) {
// do nothing for persistent instances // do nothing for persistent instances
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Persistent instance of: {0}", getLoggableName( entityName, entity ) ); LOG.trace( "Persistent instance of: " + getLoggableName( entityName, entity ) );
} }
return PERSISTENT; return PERSISTENT;
} }
// ie. e.status==DELETED // ie. e.status==DELETED
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Deleted instance of: {0}", getLoggableName( entityName, entity ) ); LOG.trace( "Deleted instance of: " + getLoggableName( entityName, entity ) );
} }
return DELETED; return DELETED;
} }
@ -61,12 +61,12 @@ public enum EntityState {
if ( ForeignKeys.isTransient( entityName, entity, assumedUnsaved, source ) ) { if ( ForeignKeys.isTransient( entityName, entity, assumedUnsaved, source ) ) {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Transient instance of: {0}", getLoggableName( entityName, entity ) ); LOG.trace( "Transient instance of: " + getLoggableName( entityName, entity ) );
} }
return TRANSIENT; return TRANSIENT;
} }
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Detached instance of: {0}", getLoggableName( entityName, entity ) ); LOG.trace( "Detached instance of: " + getLoggableName( entityName, entity ) );
} }
final PersistenceContext persistenceContext = source.getPersistenceContextInternal(); final PersistenceContext persistenceContext = source.getPersistenceContextInternal();

View File

@ -10,11 +10,12 @@ import org.hibernate.event.spi.EventSource;
import org.hibernate.internal.CoreLogging; import org.hibernate.internal.CoreLogging;
import org.hibernate.internal.CoreMessageLogger; import org.hibernate.internal.CoreMessageLogger;
import org.hibernate.persister.collection.CollectionPersister; import org.hibernate.persister.collection.CollectionPersister;
import org.hibernate.pretty.MessageHelper;
import org.hibernate.type.CollectionType; import org.hibernate.type.CollectionType;
import org.hibernate.type.CompositeType; import org.hibernate.type.CompositeType;
import org.hibernate.type.Type; import org.hibernate.type.Type;
import static org.hibernate.pretty.MessageHelper.collectionInfoString;
/** /**
* Abstract superclass of visitors that reattach collections. * Abstract superclass of visitors that reattach collections.
* *
@ -77,10 +78,8 @@ public abstract class ReattachVisitor extends ProxyVisitor {
void removeCollection(CollectionPersister role, Object collectionKey, EventSource source) void removeCollection(CollectionPersister role, Object collectionKey, EventSource source)
throws HibernateException { throws HibernateException {
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( LOG.trace( "Collection dereferenced while transient "
"Collection dereferenced while transient {0}", + collectionInfoString( role, ownerIdentifier, source.getFactory() ) );
MessageHelper.collectionInfoString( role, ownerIdentifier, source.getFactory() )
);
} }
source.getActionQueue().addAction( new CollectionRemoveAction( owner, role, collectionKey, false, source ) ); source.getActionQueue().addAction( new CollectionRemoveAction( owner, role, collectionKey, false, source ) );
} }

View File

@ -125,7 +125,7 @@ public class WrapVisitor extends ProxyVisitor {
final PersistentCollection<?> persistentCollection = collectionType.wrap( session, collection ); final PersistentCollection<?> persistentCollection = collectionType.wrap( session, collection );
persistenceContext.addNewCollection( persister, persistentCollection ); persistenceContext.addNewCollection( persister, persistentCollection );
if ( LOG.isTraceEnabled() ) { if ( LOG.isTraceEnabled() ) {
LOG.tracev( "Wrapped collection in role: {0}", collectionType.getRole() ); LOG.trace( "Wrapped collection in role: " + collectionType.getRole() );
} }
return persistentCollection; //Force a substitution! return persistentCollection; //Force a substitution!
} }