Skip to content

Commit 91a2f1d

Browse files
gavinkinggavinking
committed
improvements to TRACE-level logging
1 parent 22a84a7 commit 91a2f1d

File tree

65 files changed

+440
-387
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

65 files changed

+440
-387
lines changed

‎hibernate-core/src/main/java/org/hibernate/boot/model/internal/AnnotatedColumn.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -274,7 +274,7 @@ public void bind() {
274274
if ( generatedAs != null ) {
275275
mappingColumn.setGeneratedAs( generatedAs );
276276
}
277-
if ( LOG.isDebugEnabled() ) {
277+
if ( LOG.isDebugEnabled() && logicalColumnName != null ) {
278278
LOG.trace( "Binding column: " + logicalColumnName );
279279
}
280280
}

‎hibernate-core/src/main/java/org/hibernate/boot/registry/internal/BootstrapServiceRegistryImpl.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -292,11 +292,11 @@ public synchronized void deRegisterChild(ServiceRegistryImplementor child) {
292292
childRegistries.remove( child );
293293
if ( childRegistries.isEmpty() ) {
294294
if ( autoCloseRegistry ) {
295-
LOG.trace( "Implicitly destroying Bootstrap registry on deregistration of all child ServiceRegistries" );
295+
LOG.trace( "Automatically destroying bootstrap registry after deregistration of every child ServiceRegistry" );
296296
destroy();
297297
}
298298
else {
299-
LOG.trace( "Skipping implicitly destroying Bootstrap registry on deregistration of all child ServiceRegistries" );
299+
LOG.trace( "Skipping destroying bootstrap registry after deregistration of every child ServiceRegistry" );
300300
}
301301
}
302302
}

‎hibernate-core/src/main/java/org/hibernate/cache/spi/support/AbstractReadWriteAccess.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -106,7 +106,7 @@ public boolean putFromLoad(
106106
try {
107107
final boolean traceEnabled = log.isTraceEnabled();
108108
if ( traceEnabled ) {
109-
log.tracef( "Caching data from load [region=`%s` (%s)] : key[%s] -> value[%s]", getRegion().getName(), getAccessType(), key, value );
109+
log.tracef( "Caching data from load [region='%s' (%s)] : key[%s] -> value[%s]", getRegion().getName(), getAccessType(), key, value );
110110
}
111111
writeLock.lock();
112112
Lockable item = (Lockable) getStorageAccess().getFromCache( key, session );

‎hibernate-core/src/main/java/org/hibernate/engine/internal/NaturalIdResolutionsImpl.java‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -67,7 +67,7 @@ public boolean cacheResolution(Object id, Object naturalId, EntityMappingType en
6767
@Override
6868
public void cacheResolutionFromLoad(Object id, Object naturalId, EntityMappingType entityDescriptor) {
6969
NaturalIdLogging.NATURAL_ID_LOGGER.tracef(
70-
"Caching resolution natural-id resolution from load (%s) : `%s` -> `%s`",
70+
"Caching natural id resolution from load (%s) : '%s' -> '%s'",
7171
entityDescriptor.getEntityName(),
7272
naturalId,
7373
id
@@ -101,7 +101,7 @@ private boolean cacheResolutionLocally(Object id, Object naturalId, EntityMappin
101101
assert isValidValue( naturalId, entityDescriptor );
102102

103103
NaturalIdLogging.NATURAL_ID_LOGGER.tracef(
104-
"Locally caching natural-id resolution (%s) : `%s` -> `%s`",
104+
"Locally caching natural id resolution (%s) : '%s' -> '%s'",
105105
entityDescriptor.getEntityName(),
106106
naturalId,
107107
id
@@ -160,7 +160,7 @@ public void manageLocalResolution(
160160
@Override
161161
public Object removeLocalResolution(Object id, Object naturalId, EntityMappingType entityDescriptor) {
162162
NaturalIdLogging.NATURAL_ID_LOGGER.tracef(
163-
"Removing locally cached natural-id resolution (%s) : `%s` -> `%s`",
163+
"Removing locally cached natural id resolution (%s) : '%s' -> '%s'",
164164
entityDescriptor.getEntityName(),
165165
naturalId,
166166
id

‎hibernate-core/src/main/java/org/hibernate/engine/internal/StatefulPersistenceContext.java‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1149,7 +1149,7 @@ public void initializeNonLazyCollections() throws HibernateException {
11491149
@Override
11501150
public void initializeNonLazyCollections(Consumer<PersistentCollection<?>> initializeAction ) {
11511151
if ( loadCounter == 0 ) {
1152-
LOG.trace( "Initializing non-lazy collections" );
1152+
// LOG.trace( "Initializing non-lazy collections" );
11531153
// do this work only at the very highest level of the load
11541154
// don't let this method be called recursively
11551155
loadCounter++;
@@ -1525,7 +1525,7 @@ && isFoundInParent( propertyName, childEntity, persister, collectionPersister, p
15251525
unmergedInstance
15261526
);
15271527
LOG.tracef(
1528-
"Detached object being merged (corresponding with a managed entity) has a collection that [%s] the detached child.",
1528+
"Detached object being merged (corresponding with a managed entity) has a collection that [%s] the detached child",
15291529
( found ? "contains" : "does not contain" )
15301530
);
15311531
}
@@ -1556,7 +1556,7 @@ && isFoundInParent( propertyName, childEntity, persister, collectionPersister, p
15561556
mergeMap.get( proxy )
15571557
);
15581558
LOG.debugf(
1559-
"Detached proxy being merged has a collection that [%s] the managed child.",
1559+
"Detached proxy being merged has a collection that [%s] the managed child",
15601560
(found ? "contains" : "does not contain")
15611561
);
15621562
if ( !found ) {
@@ -1568,7 +1568,7 @@ && isFoundInParent( propertyName, childEntity, persister, collectionPersister, p
15681568
mergeMap.get( proxy )
15691569
);
15701570
LOG.debugf(
1571-
"Detached proxy being merged has a collection that [%s] the detached child being merged..",
1571+
"Detached proxy being merged has a collection that [%s] the detached child being merged",
15721572
(found ? "contains" : "does not contain")
15731573
);
15741574
}
@@ -1820,7 +1820,7 @@ public void replaceEntityEntryRowId(Object entity, Object rowId) {
18201820
* @throws IOException serialization errors.
18211821
*/
18221822
public void serialize(ObjectOutputStream oos) throws IOException {
1823-
LOG.trace( "Serializing persistence-context" );
1823+
LOG.trace( "Serializing persistence context" );
18241824

18251825
oos.writeBoolean( defaultReadOnly );
18261826
oos.writeBoolean( hasNonReadOnlyEntities );
@@ -1925,7 +1925,7 @@ private <E> void writeCollectionToStream(
19251925
public static StatefulPersistenceContext deserialize(
19261926
ObjectInputStream ois,
19271927
SessionImplementor session) throws IOException, ClassNotFoundException {
1928-
LOG.trace( "Deserializing persistence-context" );
1928+
LOG.trace( "Deserializing persistence context" );
19291929
final StatefulPersistenceContext rtn = new StatefulPersistenceContext( session );
19301930
SessionFactoryImplementor sfi = session.getFactory();
19311931

‎hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/JdbcBatchLogging.java‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -61,4 +61,12 @@ public interface JdbcBatchLogging extends BasicLogger {
6161
@LogMessage(level = TRACE)
6262
@Message("Executing JDBC batch (%s / %s) - [%s]")
6363
void executeBatch(int batchPosition, int batchSize, String string);
64+
65+
@LogMessage(level = TRACE)
66+
@Message("Conditionally executing JDBC batch - [%s]")
67+
void conditionallyExecuteBatch(String string);
68+
69+
@LogMessage(level = TRACE)
70+
@Message("Aborting JDBC batch - [%s]")
71+
void abortBatch(String string);
6472
}

‎hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/internal/BatchImpl.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -123,7 +123,7 @@ public void addToBatch(JdbcValueBindings jdbcValueBindings, TableInclusionChecke
123123
&& !inclusionChecker.include( statementDetails.getMutatingTableDetails() ) ) {
124124
if ( loggerTraceEnabled ) {
125125
MODEL_MUTATION_LOGGER.tracef(
126-
"Skipping addBatch for table : %s (batch-position=%s)",
126+
"Skipping addBatch for table: %s (batch position %s)",
127127
statementDetails.getMutatingTableDetails().getTableName(),
128128
batchPosition+1
129129
);

‎hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcCoordinatorImpl.java‎

Lines changed: 30 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@
77
import org.hibernate.ConnectionReleaseMode;
88
import org.hibernate.HibernateException;
99
import org.hibernate.TransactionException;
10-
import org.hibernate.engine.jdbc.batch.JdbcBatchLogging;
1110
import org.hibernate.engine.jdbc.batch.spi.Batch;
1211
import org.hibernate.engine.jdbc.batch.spi.BatchKey;
1312
import org.hibernate.engine.jdbc.mutation.group.PreparedStatementGroup;
@@ -39,6 +38,7 @@
3938
import java.util.function.Supplier;
4039

4140
import static org.hibernate.ConnectionReleaseMode.AFTER_STATEMENT;
41+
import static org.hibernate.engine.jdbc.batch.JdbcBatchLogging.BATCH_MESSAGE_LOGGER;
4242

4343
/**
4444
* Standard implementation of {@link JdbcCoordinator}.
@@ -81,6 +81,9 @@ public JdbcCoordinatorImpl(
8181
this.jdbcServices = jdbcServices;
8282
this.isUserSuppliedConnection = userSuppliedConnection != null;
8383
this.logicalConnection = createLogicalConnection( userSuppliedConnection, owner );
84+
if ( TRACE_ENABLED ) {
85+
LOG.tracef( "Created JdbcCoordinator @%s", hashCode() );
86+
}
8487
}
8588

8689
private static LogicalConnectionImplementor createLogicalConnection(
@@ -101,6 +104,9 @@ private JdbcCoordinatorImpl(
101104
this.isUserSuppliedConnection = isUserSuppliedConnection;
102105
this.owner = owner;
103106
this.jdbcServices = owner.getJdbcSessionContext().getJdbcServices();
107+
if ( TRACE_ENABLED ) {
108+
LOG.tracef( "Created JdbcCoordinator @%s", hashCode() );
109+
}
104110
}
105111

106112
@Override
@@ -142,7 +148,9 @@ public void flushEnding() {
142148

143149
@Override
144150
public Connection close() {
145-
if ( TRACE_ENABLED ) LOG.tracev( "Closing JDBC container [{0}]", this );
151+
if ( TRACE_ENABLED ) {
152+
LOG.tracef( "Closing JdbcCoordinator @%s", hashCode() );
153+
}
146154
Connection connection;
147155
try {
148156
if ( currentBatch != null ) {
@@ -193,7 +201,7 @@ public void executeBatch() {
193201
@Override
194202
public void conditionallyExecuteBatch(BatchKey key) {
195203
if ( currentBatch != null && !currentBatch.getKey().equals( key ) ) {
196-
JdbcBatchLogging.BATCH_LOGGER.debugf( "Conditionally executing batch - %s", currentBatch.getKey() );
204+
BATCH_MESSAGE_LOGGER.conditionallyExecuteBatch( currentBatch.getKey().toLoggableString() );
197205
try {
198206
currentBatch.execute();
199207
}
@@ -206,6 +214,7 @@ public void conditionallyExecuteBatch(BatchKey key) {
206214
@Override
207215
public void abortBatch() {
208216
if ( currentBatch != null ) {
217+
BATCH_MESSAGE_LOGGER.abortBatch( currentBatch.getKey() .toLoggableString());
209218
currentBatch.release();
210219
}
211220
}
@@ -257,7 +266,7 @@ public int determineRemainingTransactionTimeOutPeriod() {
257266
}
258267
final long millisecondsRemaining = transactionTimeOutInstant - System.currentTimeMillis();
259268
if ( millisecondsRemaining <= 0L ) {
260-
throw new TransactionException( "transaction timeout expired" );
269+
throw new TransactionException( "Transaction timeout expired" );
261270
}
262271
return Math.max( (int) (millisecondsRemaining / 1000), 1 );
263272
}
@@ -266,7 +275,8 @@ public int determineRemainingTransactionTimeOutPeriod() {
266275
public void afterStatementExecution() {
267276
final ConnectionReleaseMode connectionReleaseMode = connectionReleaseMode();
268277
if ( TRACE_ENABLED ) {
269-
LOG.tracev( "Starting after statement execution processing [{0}]", connectionReleaseMode );
278+
LOG.tracef( "Statement execution complete (connection release mode %s) in JdbcCoordinator @%s",
279+
connectionReleaseMode, hashCode() );
270280
}
271281
if ( connectionReleaseMode == AFTER_STATEMENT ) {
272282
if ( ! releasesEnabled ) {
@@ -309,7 +319,7 @@ public <T> T coordinateWork(WorkExecutorVisitable<T> work) {
309319
return result;
310320
}
311321
catch ( SQLException e ) {
312-
throw sqlExceptionHelper().convert( e, "error executing work" );
322+
throw sqlExceptionHelper().convert( e, "Error executing work" );
313323
}
314324
}
315325

@@ -323,7 +333,9 @@ public boolean isReadyForSerialization() {
323333
@Override
324334
@SuppressWarnings("unchecked")
325335
public void registerLastQuery(Statement statement) {
326-
if ( TRACE_ENABLED ) LOG.tracev( "Registering last query statement [{0}]", statement );
336+
// if ( TRACE_ENABLED ) {
337+
// LOG.tracef( "Registering last query statement [%s] @%s", statement, hashCode() );
338+
// }
327339
if ( statement instanceof JdbcWrapper ) {
328340
final JdbcWrapper<Statement> wrapper = (JdbcWrapper<Statement>) statement;
329341
registerLastQuery( wrapper.getWrappedObject() );
@@ -371,17 +383,28 @@ public boolean isActive() {
371383

372384
@Override
373385
public void afterTransactionBegin() {
386+
if ( TRACE_ENABLED ) {
387+
LOG.tracef( "Transaction after begin in JdbcCoordinator @%s", hashCode() );
388+
}
374389
owner.afterTransactionBegin();
375390
}
376391

377392
@Override
378393
public void beforeTransactionCompletion() {
394+
if ( TRACE_ENABLED ) {
395+
LOG.tracef( "Transaction before completion in JdbcCoordinator @%s", hashCode() );
396+
}
379397
owner.beforeTransactionCompletion();
380398
logicalConnection.beforeTransactionCompletion();
381399
}
382400

383401
@Override
384402
public void afterTransactionCompletion(boolean successful, boolean delayed) {
403+
if ( TRACE_ENABLED ) {
404+
LOG.tracef( "Transaction after %s completion in JdbcCoordinator @%s",
405+
successful ? "successful" : "unsuccessful",
406+
hashCode() );
407+
}
385408
afterTransaction();
386409
owner.afterTransactionCompletion( successful, delayed );
387410
}

‎hibernate-core/src/main/java/org/hibernate/engine/jdbc/mutation/internal/AbstractMutationExecutor.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -116,7 +116,7 @@ protected void performNonBatchedMutation(
116116
if ( inclusionChecker != null && !inclusionChecker.include( tableDetails ) ) {
117117
if ( MODEL_MUTATION_LOGGER.isTraceEnabled() ) {
118118
MODEL_MUTATION_LOGGER.tracef(
119-
"Skipping execution of secondary insert : %s",
119+
"Skipping execution of secondary insert: %s",
120120
tableDetails.getTableName()
121121
);
122122
}

‎hibernate-core/src/main/java/org/hibernate/engine/jdbc/mutation/internal/AbstractPreparedStatementGroup.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -45,7 +45,7 @@ protected void release(PreparedStatementDetails statementDetails) {
4545
if ( statementDetails.toRelease() ) {
4646
if ( statementDetails.getStatement() == null ) {
4747
BATCH_LOGGER.debugf(
48-
"PreparedStatementDetails did not contain PreparedStatement on #releaseStatements : %s",
48+
"PreparedStatementDetails did not contain PreparedStatement on releaseStatements: %s",
4949
statementDetails.getSqlString()
5050
);
5151
}

0 commit comments

Comments
 (0)