HHH-6258: Wrap trace and debug log statements to lessen the load on JBossLogManagerLogger.doLog. This improved throughput quite a bit.

This commit is contained in:
Andrig Miller 2011-05-25 17:40:49 -06:00 committed by Steve Ebersole
parent a917bb4b40
commit e01bb8a911
9 changed files with 60 additions and 22 deletions

View File

@ -69,7 +69,9 @@ public abstract class AbstractResultSetProxyHandler extends AbstractProxyHandler
@Override @Override
protected Object continueInvocation(Object proxy, Method method, Object[] args) throws Throwable { protected Object continueInvocation(Object proxy, Method method, Object[] args) throws Throwable {
String methodName = method.getName(); String methodName = method.getName();
LOG.trace("Handling invocation of ResultSet method [" + methodName + "]"); if (LOG.isTraceEnabled()) {
LOG.trace("Handling invocation of ResultSet method [" + methodName + "]");
}
// other methods allowed while invalid ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // other methods allowed while invalid ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
if ( "close".equals( methodName ) ) { if ( "close".equals( methodName ) ) {

View File

@ -85,7 +85,9 @@ public abstract class AbstractStatementProxyHandler extends AbstractProxyHandler
@Override @Override
protected Object continueInvocation(Object proxy, Method method, Object[] args) throws Throwable { protected Object continueInvocation(Object proxy, Method method, Object[] args) throws Throwable {
String methodName = method.getName(); String methodName = method.getName();
LOG.trace("Handling invocation of statement method [" + methodName + "]"); if (LOG.isTraceEnabled()) {
LOG.trace("Handling invocation of statement method [" + methodName + "]");
}
// other methods allowed while invalid ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // other methods allowed while invalid ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
if ( "close".equals( methodName ) ) { if ( "close".equals( methodName ) ) {

View File

@ -183,7 +183,9 @@ public class LoadContexts {
if (collectionLoadContexts == null) collectionLoadContexts = IdentityMap.instantiate(8); if (collectionLoadContexts == null) collectionLoadContexts = IdentityMap.instantiate(8);
else context = (CollectionLoadContext)collectionLoadContexts.get(resultSet); else context = (CollectionLoadContext)collectionLoadContexts.get(resultSet);
if ( context == null ) { if ( context == null ) {
LOG.trace("Constructing collection load context for result set [" + resultSet + "]"); if (LOG.isTraceEnabled()) {
LOG.trace("Constructing collection load context for result set [" + resultSet + "]");
}
context = new CollectionLoadContext( this, resultSet ); context = new CollectionLoadContext( this, resultSet );
collectionLoadContexts.put( resultSet, context ); collectionLoadContexts.put( resultSet, context );
} }

View File

@ -132,7 +132,9 @@ public class TransactionCoordinatorImpl implements TransactionCoordinator {
} }
public void afterTransaction(TransactionImplementor hibernateTransaction, int status) { public void afterTransaction(TransactionImplementor hibernateTransaction, int status) {
LOG.trace( "after transaction completion" ); if (LOG.isTraceEnabled()) {
LOG.trace( "after transaction completion" );
}
final boolean success = JtaStatusHelper.isCommitted( status ); final boolean success = JtaStatusHelper.isCommitted( status );
@ -217,7 +219,9 @@ public class TransactionCoordinatorImpl implements TransactionCoordinator {
if ( ! transactionContext.shouldAutoJoinTransaction() ) { if ( ! transactionContext.shouldAutoJoinTransaction() ) {
if ( currentHibernateTransaction.getJoinStatus() != JoinStatus.MARKED_FOR_JOINED ) { if ( currentHibernateTransaction.getJoinStatus() != JoinStatus.MARKED_FOR_JOINED ) {
LOG.debug( "Skipping JTA sync registration due to auto join checking" ); if (LOG.isDebugEnabled()) {
LOG.debug( "Skipping JTA sync registration due to auto join checking" );
}
return; return;
} }
} }
@ -235,19 +239,25 @@ public class TransactionCoordinatorImpl implements TransactionCoordinator {
// Can we resister a synchronization // Can we resister a synchronization
if ( ! jtaPlatform.canRegisterSynchronization() ) { if ( ! jtaPlatform.canRegisterSynchronization() ) {
LOG.trace( "registered JTA platform says we cannot currently resister synchronization; skipping" ); if (LOG.isTraceEnabled()) {
LOG.trace( "registered JTA platform says we cannot currently resister synchronization; skipping" );
}
return; return;
} }
// Should we resister a synchronization // Should we resister a synchronization
if ( ! transactionFactory().isJoinableJtaTransaction( this, currentHibernateTransaction ) ) { if ( ! transactionFactory().isJoinableJtaTransaction( this, currentHibernateTransaction ) ) {
LOG.trace( "TransactionFactory reported no JTA transaction to join; skipping Synchronization registration" ); if (LOG.isTraceEnabled()) {
LOG.trace( "TransactionFactory reported no JTA transaction to join; skipping Synchronization registration" );
}
return; return;
} }
jtaPlatform.registerSynchronization( new RegisteredSynchronization( getSynchronizationCallbackCoordinator() ) ); jtaPlatform.registerSynchronization( new RegisteredSynchronization( getSynchronizationCallbackCoordinator() ) );
synchronizationRegistered = true; synchronizationRegistered = true;
LOG.debug( "successfully registered Synchronization" ); if (LOG.isDebugEnabled()) {
LOG.debug( "successfully registered Synchronization" );
}
} }
@Override @Override
@ -259,7 +269,9 @@ public class TransactionCoordinatorImpl implements TransactionCoordinator {
} }
public void pulse() { public void pulse() {
LOG.trace( "Starting transaction coordinator pulse" ); if (LOG.isTraceEnabled()) {
LOG.trace( "Starting transaction coordinator pulse" );
}
if ( transactionFactory().compatibleWithJtaSynchronization() ) { if ( transactionFactory().compatibleWithJtaSynchronization() ) {
// the configured transaction strategy says it supports callbacks via JTA synchronization, so attempt to // the configured transaction strategy says it supports callbacks via JTA synchronization, so attempt to
// register JTA synchronization if possible // register JTA synchronization if possible

View File

@ -242,7 +242,9 @@ public abstract class AbstractFlushingEventListener implements Serializable {
*/ */
private void flushCollections(EventSource session) throws HibernateException { private void flushCollections(EventSource session) throws HibernateException {
LOG.trace("Processing unreferenced collections"); if (LOG.isTraceEnabled()) {
LOG.trace("Processing unreferenced collections");
}
List list = IdentityMap.entries( session.getPersistenceContext().getCollectionEntries() ); List list = IdentityMap.entries( session.getPersistenceContext().getCollectionEntries() );
int size = list.size(); int size = list.size();
@ -256,7 +258,9 @@ public abstract class AbstractFlushingEventListener implements Serializable {
// Schedule updates to collections: // Schedule updates to collections:
LOG.trace("Scheduling collection removes/(re)creates/updates"); if (LOG.isTraceEnabled()) {
LOG.trace("Scheduling collection removes/(re)creates/updates");
}
list = IdentityMap.entries( session.getPersistenceContext().getCollectionEntries() ); list = IdentityMap.entries( session.getPersistenceContext().getCollectionEntries() );
size = list.size(); size = list.size();

View File

@ -854,12 +854,16 @@ public abstract class Loader {
EntityKey[] keys = new EntityKey[entitySpan]; //we can reuse it for each row EntityKey[] keys = new EntityKey[entitySpan]; //we can reuse it for each row
LOG.trace("Processing result set"); if (LOG.isTraceEnabled()) {
LOG.trace("Processing result set");
}
int count; int count;
for ( count = 0; count < maxRows && rs.next(); count++ ) { for ( count = 0; count < maxRows && rs.next(); count++ ) {
LOG.debugf("Result set row: %s", count); if (LOG.isDebugEnabled()) {
LOG.debugf("Result set row: %s", count);
}
Object result = getRowFromResultSet( Object result = getRowFromResultSet(
rs, rs,
@ -881,7 +885,9 @@ public abstract class Loader {
} }
LOG.trace("Done processing result set (" + count + " rows)"); if (LOG.isTraceEnabled()) {
LOG.trace("Done processing result set (" + count + " rows)");
}
} }
finally { finally {

View File

@ -74,7 +74,9 @@ public final class ServiceBinding<R extends Service> {
public void setService(R service) { public void setService(R service) {
if ( this.service != null ) { if ( this.service != null ) {
log.debug( "Overriding existing service binding [" + serviceRole.getName() + "]" ); if (log.isDebugEnabled()) {
log.debug( "Overriding existing service binding [" + serviceRole.getName() + "]" );
}
} }
this.service = service; this.service = service;
} }

View File

@ -65,14 +65,18 @@ public abstract class BasicBinder<J> implements ValueBinder<J> {
*/ */
public final void bind(PreparedStatement st, J value, int index, WrapperOptions options) throws SQLException { public final void bind(PreparedStatement st, J value, int index, WrapperOptions options) throws SQLException {
if ( value == null ) { if ( value == null ) {
LOG.trace(String.format(NULL_BIND_MSG_TEMPLATE, index, JdbcTypeNameMapper.getTypeName(sqlDescriptor.getSqlType()))); if (LOG.isTraceEnabled()) {
LOG.trace(String.format(NULL_BIND_MSG_TEMPLATE, index, JdbcTypeNameMapper.getTypeName(sqlDescriptor.getSqlType())));
}
st.setNull( index, sqlDescriptor.getSqlType() ); st.setNull( index, sqlDescriptor.getSqlType() );
} }
else { else {
LOG.trace(String.format(BIND_MSG_TEMPLATE, if (LOG.isTraceEnabled()) {
index, LOG.trace(String.format(BIND_MSG_TEMPLATE,
JdbcTypeNameMapper.getTypeName(sqlDescriptor.getSqlType()), index,
getJavaDescriptor().extractLoggableRepresentation(value))); JdbcTypeNameMapper.getTypeName(sqlDescriptor.getSqlType()),
getJavaDescriptor().extractLoggableRepresentation(value)));
}
doBind( st, value, index, options ); doBind( st, value, index, options );
} }
} }

View File

@ -62,11 +62,15 @@ public abstract class BasicExtractor<J> implements ValueExtractor<J> {
public J extract(ResultSet rs, String name, WrapperOptions options) throws SQLException { public J extract(ResultSet rs, String name, WrapperOptions options) throws SQLException {
final J value = doExtract( rs, name, options ); final J value = doExtract( rs, name, options );
if ( value == null || rs.wasNull() ) { if ( value == null || rs.wasNull() ) {
LOG.trace("Found [null] as column [" + name + "]"); if (LOG.isTraceEnabled()) {
LOG.trace("Found [null] as column [" + name + "]");
}
return null; return null;
} }
else { else {
LOG.trace("Found [" + getJavaDescriptor().extractLoggableRepresentation(value) + "] as column [" + name + "]"); if (LOG.isTraceEnabled()) {
LOG.trace("Found [" + getJavaDescriptor().extractLoggableRepresentation(value) + "] as column [" + name + "]");
}
return value; return value;
} }
} }