Skip to content

Commit

Permalink
HHH-7908 Logging level checking
Browse files Browse the repository at this point in the history 
Conflicts:
	hibernate-core/src/main/java/org/hibernate/internal/SessionFactoryImpl.java
  • Loading branch information
@brmeyer
Nikolay Shestakov authored and brmeyer committed Apr 12, 2013
1 parent 03daecf commit cbbadea
Show file tree
Hide file tree
Showing 26 changed files with 139 additions and 84 deletions.
12 changes: 7 additions & 5 deletions ...rnate-core/src/main/java/org/hibernate/action/internal/UnresolvedEntityInsertActions.java
View file
Expand Up @@ -204,11 +204,13 @@ public Set<AbstractEntityInsertAction> resolveDependentActions(Object managedEnt
if ( entityEntry.getStatus() != Status.MANAGED && entityEntry.getStatus() != Status.READ_ONLY ) {
throw new IllegalArgumentException( "EntityEntry did not have status MANAGED or READ_ONLY: " + entityEntry );
}

final boolean traceEnabled = LOG.isTraceEnabled();
// Find out if there are any unresolved insertions that are waiting for the
// specified entity to be resolved.
Set<AbstractEntityInsertAction> dependentActions = dependentActionsByTransientEntity.remove( managedEntity );
if ( dependentActions == null ) {
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev(
"No unresolved entity inserts that depended on [{0}]",
MessageHelper.infoString( entityEntry.getEntityName(), entityEntry.getId() )
Expand All @@ -217,15 +219,15 @@ public Set<AbstractEntityInsertAction> resolveDependentActions(Object managedEnt
return Collections.emptySet(); //NOTE EARLY EXIT!
}
Set<AbstractEntityInsertAction> resolvedActions = new IdentitySet( );
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev(
"Unresolved inserts before resolving [{0}]: [{1}]",
MessageHelper.infoString( entityEntry.getEntityName(), entityEntry.getId() ),
toString()
);
}
for ( AbstractEntityInsertAction dependentAction : dependentActions ) {
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev(
"Resolving insert [{0}] dependency on [{1}]",
MessageHelper.infoString( dependentAction.getEntityName(), dependentAction.getId() ),
Expand All @@ -235,7 +237,7 @@ public Set<AbstractEntityInsertAction> resolveDependentActions(Object managedEnt
NonNullableTransientDependencies dependencies = dependenciesByAction.get( dependentAction );
dependencies.resolveNonNullableTransientEntity( managedEntity );
if ( dependencies.isEmpty() ) {
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev(
"Resolving insert [{0}] (only depended on [{1}])",
dependentAction,
Expand All @@ -247,7 +249,7 @@ public Set<AbstractEntityInsertAction> resolveDependentActions(Object managedEnt
resolvedActions.add( dependentAction );
}
}
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev(
"Unresolved inserts after resolving [{0}]: [{1}]",
MessageHelper.infoString( entityEntry.getEntityName(), entityEntry.getId() ),
Expand Down
7 changes: 4 additions & 3 deletions hibernate-core/src/main/java/org/hibernate/cfg/AnnotationBinder.java
View file
Expand Up @@ -1476,7 +1476,8 @@ private static void processElementAnnotations(
* ordering does not matter
*/

if ( LOG.isTraceEnabled() ) {
final boolean traceEnabled = LOG.isTraceEnabled();
if ( traceEnabled ) {
LOG.tracev( "Processing annotations of {0}.{1}" , propertyHolder.getEntityName(), inferredData.getPropertyName() );
}

Expand Down Expand Up @@ -1542,7 +1543,7 @@ private static void processElementAnnotations(
+ propertyHolder.getEntityName()
);
}
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "{0} is a version property", inferredData.getPropertyName() );
}
RootClass rootClass = ( RootClass ) propertyHolder.getPersistentClass();
Expand All @@ -1568,7 +1569,7 @@ private static void processElementAnnotations(
SimpleValue simpleValue = ( SimpleValue ) prop.getValue();
simpleValue.setNullValue( "undefined" );
rootClass.setOptimisticLockMode( Versioning.OPTIMISTIC_LOCK_VERSION );
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Version name: {0}, unsavedValue: {1}", rootClass.getVersion().getName(),
( (SimpleValue) rootClass.getVersion().getValue() ).getNullValue() );
}
Expand Down
7 changes: 5 additions & 2 deletions hibernate-core/src/main/java/org/hibernate/cfg/CollectionSecondPass.java
View file
Expand Up @@ -61,12 +61,15 @@ public CollectionSecondPass(Mappings mappings, Collection collection) {

public void doSecondPass(java.util.Map persistentClasses)
throws MappingException {
LOG.debugf( "Second pass for collection: %s", collection.getRole() );
final boolean debugEnabled = LOG.isDebugEnabled();
if ( debugEnabled ) {
LOG.debugf( "Second pass for collection: %s", collection.getRole() );
}

secondPass( persistentClasses, localInheritedMetas ); // using local since the inheritedMetas at this point is not the correct map since it is always the empty map
collection.createAllKeys();

if ( LOG.isDebugEnabled() ) {
if ( debugEnabled ) {
String msg = "Mapped collection key: " + columns( collection.getKey() );
if ( collection.isIndexed() )
msg += ", index: " + columns( ( (IndexedCollection) collection ).getIndex() );
Expand Down
3 changes: 2 additions & 1 deletion hibernate-core/src/main/java/org/hibernate/cfg/HbmBinder.java
View file
Expand Up @@ -2657,6 +2657,7 @@ private static void bindManyToManySubelements(
"not valid within collection using join fetching [" + collection.getRole() + "]"
);
}
final boolean debugEnabled = LOG.isDebugEnabled();
while ( filters.hasNext() ) {
final Element filterElement = ( Element ) filters.next();
final String name = filterElement.attributeValue( "name" );
Expand All @@ -2674,7 +2675,7 @@ private static void bindManyToManySubelements(
Element alias = (Element) aliasesIterator.next();
aliasTables.put(alias.attributeValue("alias"), alias.attributeValue("table"));
}
if ( LOG.isDebugEnabled() ) {
if ( debugEnabled ) {
LOG.debugf( "Applying many-to-many filter [%s] as [%s] to role [%s]", name, condition, collection.getRole() );
}
String autoAliasInjectionText = filterElement.attributeValue("autoAliasInjection");
Expand Down
6 changes: 4 additions & 2 deletions hibernate-core/src/main/java/org/hibernate/cfg/annotations/CollectionBinder.java
View file
Expand Up @@ -814,7 +814,9 @@ protected void bindOneToManySecondPass(
boolean ignoreNotFound,
Mappings mappings,
Map<XClass, InheritanceState> inheritanceStatePerClass) {
if ( LOG.isDebugEnabled() ) {

final boolean debugEnabled = LOG.isDebugEnabled();
if ( debugEnabled ) {
LOG.debugf( "Binding a OneToMany: %s.%s through a foreign key", propertyHolder.getEntityName(), propertyName );
}
org.hibernate.mapping.OneToMany oneToMany = new org.hibernate.mapping.OneToMany( mappings, collection.getOwner() );
Expand Down Expand Up @@ -855,7 +857,7 @@ protected void bindOneToManySecondPass(
column.setJoins( joins );
collection.setCollectionTable( column.getTable() );
}
if ( LOG.isDebugEnabled() ) {
if ( debugEnabled ) {
LOG.debugf( "Mapping collection: %s -> %s", collection.getRole(), collection.getCollectionTable().getName() );
}
bindFilters( false );
Expand Down
15 changes: 9 additions & 6 deletions hibernate-core/src/main/java/org/hibernate/engine/internal/Cascade.java
View file
Expand Up @@ -146,7 +146,8 @@ public void cascade(final EntityPersister persister, final Object parent, final
throws HibernateException {

if ( persister.hasCascades() || action.requiresNoCascadeChecking() ) { // performance opt
if ( LOG.isTraceEnabled() ) {
final boolean traceEnabled = LOG.isTraceEnabled();
if ( traceEnabled ) {
LOG.tracev( "Processing cascade {0} for: {1}", action, persister.getEntityName() );
}

Expand Down Expand Up @@ -183,7 +184,7 @@ else if ( action.requiresNoCascadeChecking() ) {
}
}

if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Done processing cascade {0} for: {1}", action, persister.getEntityName() );
}
}
Expand Down Expand Up @@ -407,7 +408,8 @@ private void cascadeCollectionElements(
boolean reallyDoCascade = style.reallyDoCascade(action) && child!=CollectionType.UNFETCHED_COLLECTION;

if ( reallyDoCascade ) {
if ( LOG.isTraceEnabled() ) {
final boolean traceEnabled = LOG.isTraceEnabled();
if ( traceEnabled ) {
LOG.tracev( "Cascade {0} for collection: {1}", action, collectionType.getRole() );
}

Expand All @@ -424,7 +426,7 @@ private void cascadeCollectionElements(
);
}

if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Done cascade {0} for collection: {1}", action, collectionType.getRole() );
}
}
Expand All @@ -435,7 +437,8 @@ private void cascadeCollectionElements(
child instanceof PersistentCollection; //a newly instantiated collection can't have orphans

if ( deleteOrphans ) { // handle orphaned entities!!
if ( LOG.isTraceEnabled() ) {
final boolean traceEnabled = LOG.isTraceEnabled();
if ( traceEnabled ) {
LOG.tracev( "Deleting orphans for collection: {0}", collectionType.getRole() );
}
// we can do the cast since orphan-delete does not apply to:
Expand All @@ -444,7 +447,7 @@ private void cascadeCollectionElements(
final String entityName = collectionType.getAssociatedEntityName( eventSource.getFactory() );
deleteOrphans( entityName, (PersistentCollection) child );

if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Done deleting orphans for collection: {0}", collectionType.getRole() );
}
}
Expand Down
2 changes: 1 addition & 1 deletion hibernate-core/src/main/java/org/hibernate/engine/internal/Collections.java
View file
Expand Up @@ -72,7 +72,7 @@ private static void processDereferencedCollection(PersistentCollection coll, Ses
CollectionEntry entry = persistenceContext.getCollectionEntry(coll);
final CollectionPersister loadedPersister = entry.getLoadedPersister();

if ( LOG.isDebugEnabled() && loadedPersister != null ) {
if ( loadedPersister != null && LOG.isDebugEnabled() ) {
LOG.debugf(
"Collection dereferenced: %s",
MessageHelper.collectionInfoString( loadedPersister,
Expand Down
3 changes: 2 additions & 1 deletion hibernate-core/src/main/java/org/hibernate/engine/internal/ParameterBinder.java
View file
Expand Up @@ -112,6 +112,7 @@ public static int bindNamedParameters(
final NamedParameterSource source,
final SessionImplementor session) throws SQLException, HibernateException {
if ( namedParams != null ) {
final boolean debugEnabled = LOG.isDebugEnabled();
// assumes that types are all of span 1
Iterator iter = namedParams.entrySet().iterator();
int result = 0;
Expand All @@ -121,7 +122,7 @@ public static int bindNamedParameters(
TypedValue typedval = (TypedValue) e.getValue();
int[] locations = source.getNamedParameterLocations( name );
for ( int i = 0; i < locations.length; i++ ) {
if ( LOG.isDebugEnabled() ) {
if ( debugEnabled ) {
LOG.debugf("bindNamedParameters() %s -> %s [%s]", typedval.getValue(), name, locations[i] + start);
}
typedval.getType().nullSafeSet( ps, typedval.getValue(), locations[i] + start, session );
Expand Down
9 changes: 5 additions & 4 deletions hibernate-core/src/main/java/org/hibernate/engine/internal/TwoPhaseLoad.java
View file
Expand Up @@ -101,7 +101,7 @@ public static void postHydrate(
lazyPropertiesAreUnfetched
);

if ( LOG.isTraceEnabled() && version != null ) {
if ( version != null && LOG.isTraceEnabled() ) {
String versionStr = persister.isVersioned()
? persister.getVersionType().toLoggableString( version, session.getFactory() )
: "null";
Expand Down Expand Up @@ -153,7 +153,8 @@ private static void doInitializeEntity(
Serializable id = entityEntry.getId();
Object[] hydratedState = entityEntry.getLoadedState();

if ( LOG.isDebugEnabled() ) {
final boolean debugEnabled = LOG.isDebugEnabled();
if ( debugEnabled ) {
LOG.debugf(
"Resolving associations for %s",
MessageHelper.infoString( persister, id, session.getFactory() )
Expand Down Expand Up @@ -187,7 +188,7 @@ private static void doInitializeEntity(
final SessionFactoryImplementor factory = session.getFactory();
if ( persister.hasCache() && session.getCacheMode().isPutEnabled() ) {

if ( LOG.isDebugEnabled() ) {
if ( debugEnabled ) {
LOG.debugf(
"Adding entity to second-level cache: %s",
MessageHelper.infoString( persister, id, session.getFactory() )
Expand Down Expand Up @@ -272,7 +273,7 @@ private static void doInitializeEntity(
session
);

if ( LOG.isDebugEnabled() ) {
if ( debugEnabled ) {
LOG.debugf(
"Done materializing entity %s",
MessageHelper.infoString( persister, id, session.getFactory() )
Expand Down
9 changes: 6 additions & 3 deletions hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlExceptionHelper.java
View file
Expand Up @@ -136,11 +136,14 @@ public void logExceptions( SQLException sqlException,
if (LOG.isEnabled(Level.ERROR)) {
if (LOG.isDebugEnabled()) {
message = StringHelper.isNotEmpty(message) ? message : DEFAULT_EXCEPTION_MSG;
LOG.debug( message, sqlException );
LOG.debug( message, sqlException );
}
final boolean warnEnabled = LOG.isEnabled( Level.WARN );
while (sqlException != null) {
StringBuilder buf = new StringBuilder(30).append("SQL Error: ").append(sqlException.getErrorCode()).append(", SQLState: ").append(sqlException.getSQLState());
LOG.warn(buf.toString());
if ( warnEnabled ) {
StringBuilder buf = new StringBuilder(30).append("SQL Error: ").append(sqlException.getErrorCode()).append(", SQLState: ").append(sqlException.getSQLState());
LOG.warn(buf.toString());
}
LOG.error(sqlException.getMessage());
sqlException = sqlException.getNextException();
}
Expand Down
14 changes: 9 additions & 5 deletions ...rnate-core/src/main/java/org/hibernate/engine/loading/internal/CollectionLoadContext.java
View file
Expand Up @@ -219,20 +219,21 @@ else if ( lce.getResultSet() == resultSet && lce.getPersister() == persister ) {
}

private void endLoadingCollections(CollectionPersister persister, List matchedCollectionEntries) {
final boolean debugEnabled = LOG.isDebugEnabled();
if ( matchedCollectionEntries == null ) {
if ( LOG.isDebugEnabled()) LOG.debugf( "No collections were found in result set for role: %s", persister.getRole() );
if ( debugEnabled ) LOG.debugf( "No collections were found in result set for role: %s", persister.getRole() );
return;
}

final int count = matchedCollectionEntries.size();
if ( LOG.isDebugEnabled()) LOG.debugf("%s collections were found in result set for role: %s", count, persister.getRole());
if ( debugEnabled ) LOG.debugf("%s collections were found in result set for role: %s", count, persister.getRole());

for ( int i = 0; i < count; i++ ) {
LoadingCollectionEntry lce = ( LoadingCollectionEntry ) matchedCollectionEntries.get( i );
endLoadingCollection( lce, persister );
}

if ( LOG.isDebugEnabled() ) LOG.debugf( "%s collections initialized for role: %s", count, persister.getRole() );
if ( debugEnabled ) LOG.debugf( "%s collections initialized for role: %s", count, persister.getRole() );
}

private void endLoadingCollection(LoadingCollectionEntry lce, CollectionPersister persister) {
Expand Down Expand Up @@ -287,13 +288,16 @@ private void addCollectionToCache(LoadingCollectionEntry lce, CollectionPersiste
final SessionImplementor session = getLoadContext().getPersistenceContext().getSession();
final SessionFactoryImplementor factory = session.getFactory();

if ( LOG.isDebugEnabled() ) {
final boolean debugEnabled = LOG.isDebugEnabled();
if ( debugEnabled ) {
LOG.debugf( "Caching collection: %s", MessageHelper.collectionInfoString( persister, lce.getCollection(), lce.getKey(), session ) );
}

if ( !session.getEnabledFilters().isEmpty() && persister.isAffectedByEnabledFilters( session ) ) {
// some filters affecting the collection are enabled on the session, so do not do the put into the cache.
LOG.debug( "Refusing to add to cache due to enabled filters" );
if ( debugEnabled ) {
LOG.debug( "Refusing to add to cache due to enabled filters" );
}
// todo : add the notion of enabled filters to the CacheKey to differentiate filtered collections from non-filtered;
// but CacheKey is currently used for both collections and entities; would ideally need to define two seperate ones;
// currently this works in conjuction with the check on
Expand Down
9 changes: 5 additions & 4 deletions hibernate-core/src/main/java/org/hibernate/event/internal/AbstractSaveEventListener.java
View file
Expand Up @@ -472,18 +472,19 @@ protected EntityState getEntityState(
EntityEntry entry, //pass this as an argument only to avoid double looking
SessionImplementor source) {

final boolean traceEnabled = LOG.isTraceEnabled();
if ( entry != null ) { // the object is persistent

//the entity is associated with the session, so check its status
if ( entry.getStatus() != Status.DELETED ) {
// do nothing for persistent instances
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Persistent instance of: {0}", getLoggableName( entityName, entity ) );
}
return EntityState.PERSISTENT;
}
// ie. e.status==DELETED
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Deleted instance of: {0}", getLoggableName( entityName, entity ) );
}
return EntityState.DELETED;
Expand All @@ -494,12 +495,12 @@ protected EntityState getEntityState(
// try interceptor and unsaved-value

if ( ForeignKeys.isTransient( entityName, entity, getAssumedUnsaved(), source )) {
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Transient instance of: {0}", getLoggableName( entityName, entity ) );
}
return EntityState.TRANSIENT;
}
if ( LOG.isTraceEnabled() ) {
if ( traceEnabled ) {
LOG.tracev( "Detached instance of: {0}", getLoggableName( entityName, entity ) );
}
return EntityState.DETACHED;
Expand Down
2 changes: 1 addition & 1 deletion ...nate-core/src/main/java/org/hibernate/event/internal/DefaultFlushEntityEventListener.java
View file
Expand Up @@ -633,7 +633,7 @@ public int[] visitAttributes(CustomEntityDirtinessStrategy.AttributeChecker attr
}

private void logDirtyProperties(Serializable id, int[] dirtyProperties, EntityPersister persister) {
if ( LOG.isTraceEnabled() && dirtyProperties != null && dirtyProperties.length > 0 ) {
if ( dirtyProperties != null && dirtyProperties.length > 0 && LOG.isTraceEnabled() ) {
final String[] allPropertyNames = persister.getPropertyNames();
final String[] dirtyPropertyNames = new String[ dirtyProperties.length ];
for ( int i = 0; i < dirtyProperties.length; i++ ) {
Expand Down
15 changes: 10 additions & 5 deletions .../src/main/java/org/hibernate/event/internal/DefaultInitializeCollectionEventListener.java
View file
Expand Up @@ -59,26 +59,31 @@ public void onInitializeCollection(InitializeCollectionEvent event)
CollectionEntry ce = source.getPersistenceContext().getCollectionEntry(collection);
if (ce==null) throw new HibernateException("collection was evicted");
if ( !collection.wasInitialized() ) {
if ( LOG.isTraceEnabled() ) {
final boolean traceEnabled = LOG.isTraceEnabled();
if ( traceEnabled ) {
LOG.tracev( "Initializing collection {0}",
MessageHelper.collectionInfoString( ce.getLoadedPersister(), collection, ce.getLoadedKey(), source ) );
LOG.trace( "Checking second-level cache" );
}

LOG.trace( "Checking second-level cache" );
final boolean foundInCache = initializeCollectionFromCache(
ce.getLoadedKey(),
ce.getLoadedPersister(),
collection,
source
);

if ( foundInCache ) {
if ( foundInCache && traceEnabled ) {

This comment has been minimized.

Sign in to view

Copy link
@jiri-pejchal

jiri-pejchal May 16, 2013

Contributor

This change broke the collection cache in DefaultInitializeCollectionEventListener. SQL query is executed even if collection is found in cache. The 'if' statement has 'else' branch.

Instead of

if ( foundInCache &&  traceEnabled ) {
         LOG.trace( "Collection initialized from cache" ); 
    }
} else {

it should be:

if ( foundInCache ) {
    if ( traceEnabled ) {
         LOG.trace( "Collection initialized from cache" ); 
    }
} else {
}

https://hibernate.atlassian.net/browse/HHH-8250
LOG.trace( "Collection initialized from cache" );
}
else {
LOG.trace( "Collection not cached" );
if ( traceEnabled ) {
LOG.trace( "Collection not cached" );
}
ce.getLoadedPersister().initialize( ce.getLoadedKey(), source );
LOG.trace( "Collection initialized" );
if ( traceEnabled ) {
LOG.trace( "Collection initialized" );
}

if ( source.getFactory().getStatistics().isStatisticsEnabled() ) {
source.getFactory().getStatisticsImplementor().fetchCollection(
Expand Down

0 comments on commit cbbadea

Please sign in to comment.