From aa6f88f1b4c1d6bba4a0c6ec30746bd181347c20 Mon Sep 17 00:00:00 2001 From: Gavin King Date: Fri, 4 Oct 2024 08:54:40 +0200 Subject: [PATCH] move some logging in BatchImpl to typed methods + very minor code cleanups in BatchImpl & JdbcCoordinatorImpl --- .../engine/jdbc/batch/JdbcBatchLogging.java | 15 +- .../engine/jdbc/batch/internal/BatchImpl.java | 157 ++++++++---------- .../jdbc/internal/JdbcCoordinatorImpl.java | 78 ++++----- 3 files changed, 126 insertions(+), 124 deletions(-) diff --git a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/JdbcBatchLogging.java b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/JdbcBatchLogging.java index 75f590ae1e..f95f448667 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/JdbcBatchLogging.java +++ b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/JdbcBatchLogging.java @@ -16,6 +16,7 @@ import org.jboss.logging.annotations.ValidIdRange; import java.lang.invoke.MethodHandles; import static org.jboss.logging.Logger.Level.INFO; +import static org.jboss.logging.Logger.Level.TRACE; import static org.jboss.logging.Logger.Level.WARN; /** @@ -36,10 +37,22 @@ public interface JdbcBatchLogging extends BasicLogger { JdbcBatchLogging BATCH_MESSAGE_LOGGER = Logger.getMessageLogger( MethodHandles.lookup(), JdbcBatchLogging.class, NAME ); @LogMessage(level = WARN) - @Message(id = 100502, value = "Unable to release batch statement...") + @Message(id = 100502, value = "Unable to release batch statement") void unableToReleaseBatchStatement(); @LogMessage(level = INFO) @Message(id=100503, value = "On release of batch it still contained JDBC statements") void batchContainedStatementsOnRelease(); + + @LogMessage(level = TRACE) + @Message("Created JDBC batch (%s) - [%s]") + void createBatch(int batchSize, String string); + + @LogMessage(level = TRACE) + @Message("Adding to JDBC batch (%s / %s) - [%s]") + void addToBatch(int batchPosition, int batchSize, String string); + + @LogMessage(level = TRACE) + @Message("Executing JDBC batch (%s / %s) - [%s]") + void executeBatch(int batchPosition, int batchSize, String string); } diff --git a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/internal/BatchImpl.java b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/internal/BatchImpl.java index 5ccc7430ca..86b59d2a6f 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/internal/BatchImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/batch/internal/BatchImpl.java @@ -32,7 +32,7 @@ import static org.hibernate.engine.jdbc.batch.JdbcBatchLogging.BATCH_MESSAGE_LOG import static org.hibernate.sql.model.ModelMutationLogging.MODEL_MUTATION_LOGGER; /** - * Standard implementation of Batch + * Standard implementation of {@link Batch} * * @author Steve Ebersole */ @@ -63,6 +63,7 @@ public class BatchImpl implements Batch { throw new IllegalArgumentException( "JDBC coordinator cannot be null" ); } + this.batchSizeToUse = batchSizeToUse; this.key = key; this.jdbcCoordinator = jdbcCoordinator; this.statementGroup = statementGroup; @@ -71,11 +72,8 @@ public class BatchImpl implements Batch { this.sqlStatementLogger = jdbcServices.getSqlStatementLogger(); this.sqlExceptionHelper = jdbcServices.getSqlExceptionHelper(); - this.batchSizeToUse = batchSizeToUse; - if ( BATCH_LOGGER.isTraceEnabled() ) { - BATCH_LOGGER.tracef( - "Created Batch (%s) - `%s`", + BATCH_MESSAGE_LOGGER.createBatch( batchSizeToUse, key.toLoggableString() ); @@ -114,16 +112,17 @@ public class BatchImpl implements Batch { public void addToBatch(JdbcValueBindings jdbcValueBindings, TableInclusionChecker inclusionChecker) { final boolean loggerTraceEnabled = BATCH_LOGGER.isTraceEnabled(); if ( loggerTraceEnabled ) { - BATCH_LOGGER.tracef( - "Adding to JDBC batch (%s) - `%s`", + BATCH_MESSAGE_LOGGER.addToBatch( batchPosition + 1, + batchSizeToUse, getKey().toLoggableString() ); } try { getStatementGroup().forEachStatement( (tableName, statementDetails) -> { - if ( inclusionChecker != null && !inclusionChecker.include( statementDetails.getMutatingTableDetails() ) ) { + if ( inclusionChecker != null + && !inclusionChecker.include( statementDetails.getMutatingTableDetails() ) ) { if ( loggerTraceEnabled ) { MODEL_MUTATION_LOGGER.tracef( "Skipping addBatch for table : %s (batch-position=%s)", @@ -131,27 +130,26 @@ public class BatchImpl implements Batch { batchPosition+1 ); } - return; } - - //noinspection resource - final PreparedStatement statement = statementDetails.resolveStatement(); - sqlStatementLogger.logStatement( statementDetails.getSqlString() ); - jdbcValueBindings.beforeStatement( statementDetails ); - - try { - statement.addBatch(); - } - catch (SQLException e) { - BATCH_LOGGER.debug( "SQLException escaped proxy", e ); - throw sqlExceptionHelper.convert( - e, - "Could not perform addBatch", - statementDetails.getSqlString() - ); - } - finally { - jdbcValueBindings.afterStatement( statementDetails.getMutatingTableDetails() ); + else { + //noinspection resource + final PreparedStatement statement = statementDetails.resolveStatement(); + sqlStatementLogger.logStatement( statementDetails.getSqlString() ); + jdbcValueBindings.beforeStatement( statementDetails ); + try { + statement.addBatch(); + } + catch (SQLException e) { + BATCH_LOGGER.debug( "SQLException escaped proxy", e ); + throw sqlExceptionHelper.convert( + e, + "Could not perform addBatch", + statementDetails.getSqlString() + ); + } + finally { + jdbcValueBindings.afterStatement( statementDetails.getMutatingTableDetails() ); + } } } ); } @@ -176,10 +174,10 @@ public class BatchImpl implements Batch { "PreparedStatementDetails did not contain PreparedStatement on #releaseStatements : %s", statementDetails.getSqlString() ); - return; } - - clearBatch( statementDetails ); + else { + clearBatch( statementDetails ); + } } ); statementGroup.release(); @@ -236,34 +234,29 @@ public class BatchImpl implements Batch { @Override public void execute() { notifyObserversExplicitExecution(); - if ( getStatementGroup().getNumberOfStatements() == 0 ) { - return; - } - - try { - if ( batchPosition == 0 ) { - if( !batchExecuted) { - if ( BATCH_LOGGER.isDebugEnabled() ) { + if ( getStatementGroup().getNumberOfStatements() != 0 ) { + try { + if ( batchPosition == 0 ) { + if ( !batchExecuted && BATCH_LOGGER.isDebugEnabled() ) { BATCH_LOGGER.debugf( "No batched statements to execute - %s", getKey().toLoggableString() ); } } + else { + performExecution(); + } } - else { - performExecution(); + finally { + releaseStatements(); } } - finally { - releaseStatements(); - } } protected void performExecution() { if ( BATCH_LOGGER.isTraceEnabled() ) { - BATCH_LOGGER.tracef( - "Executing JDBC batch (%s / %s) - `%s`", + BATCH_MESSAGE_LOGGER.executeBatch( batchPosition, batchSizeToUse, getKey().toLoggableString() @@ -276,37 +269,34 @@ public class BatchImpl implements Batch { getStatementGroup().forEachStatement( (tableName, statementDetails) -> { final String sql = statementDetails.getSqlString(); final PreparedStatement statement = statementDetails.getStatement(); - - if ( statement == null ) { - return; - } - - try { - if ( statementDetails.getMutatingTableDetails().isIdentifierTable() ) { - final int[] rowCounts; - final EventManager eventManager = jdbcSessionOwner.getEventManager(); - final HibernateMonitoringEvent jdbcBatchExecutionEvent = eventManager.beginJdbcBatchExecutionEvent(); - try { - eventHandler.jdbcExecuteBatchStart(); - rowCounts = statement.executeBatch(); + if ( statement != null ) { + try { + if ( statementDetails.getMutatingTableDetails().isIdentifierTable() ) { + final int[] rowCounts; + final EventManager eventManager = jdbcSessionOwner.getEventManager(); + final HibernateMonitoringEvent executionEvent = eventManager.beginJdbcBatchExecutionEvent(); + try { + eventHandler.jdbcExecuteBatchStart(); + rowCounts = statement.executeBatch(); + } + finally { + eventManager.completeJdbcBatchExecutionEvent( executionEvent, sql ); + eventHandler.jdbcExecuteBatchEnd(); + } + checkRowCounts( rowCounts, statementDetails ); } - finally { - eventManager.completeJdbcBatchExecutionEvent( jdbcBatchExecutionEvent, sql ); - eventHandler.jdbcExecuteBatchEnd(); + else { + statement.executeBatch(); } - checkRowCounts( rowCounts, statementDetails ); } - else { - statement.executeBatch(); + catch (SQLException e) { + abortBatch( e ); + throw sqlExceptionHelper.convert( e, "could not execute batch", sql ); + } + catch (RuntimeException re) { + abortBatch( re ); + throw re; } - } - catch (SQLException e) { - abortBatch( e ); - throw sqlExceptionHelper.convert( e, "could not execute batch", sql ); - } - catch (RuntimeException re) { - abortBatch( re ); - throw re; } } ); } @@ -318,14 +308,12 @@ public class BatchImpl implements Batch { private void checkRowCounts(int[] rowCounts, PreparedStatementDetails statementDetails) throws SQLException, HibernateException { final int numberOfRowCounts = rowCounts.length; - if ( batchPosition != 0 ) { - if ( numberOfRowCounts != batchPosition ) { - JDBC_MESSAGE_LOGGER.unexpectedRowCounts( - statementDetails.getMutatingTableDetails().getTableName(), - numberOfRowCounts, - batchPosition - ); - } + if ( batchPosition != 0 && numberOfRowCounts != batchPosition ) { + JDBC_MESSAGE_LOGGER.unexpectedRowCounts( + statementDetails.getMutatingTableDetails().getTableName(), + numberOfRowCounts, + batchPosition + ); } for ( int i = 0; i < numberOfRowCounts; i++ ) { @@ -345,10 +333,9 @@ public class BatchImpl implements Batch { public void release() { if ( BATCH_MESSAGE_LOGGER.isInfoEnabled() ) { final PreparedStatementGroup statementGroup = getStatementGroup(); - if ( statementGroup.getNumberOfStatements() != 0 ) { - if ( statementGroup.hasMatching( (statementDetails) -> statementDetails.getStatement() != null ) ) { - BATCH_MESSAGE_LOGGER.batchContainedStatementsOnRelease(); - } + if ( statementGroup.getNumberOfStatements() != 0 + && statementGroup.hasMatching( statementDetails -> statementDetails.getStatement() != null ) ) { + BATCH_MESSAGE_LOGGER.batchContainedStatementsOnRelease(); } } releaseStatements(); diff --git a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcCoordinatorImpl.java b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcCoordinatorImpl.java index eb12ba57d6..8581b10f00 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcCoordinatorImpl.java +++ b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcCoordinatorImpl.java @@ -80,7 +80,8 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { JdbcServices jdbcServices) { this.isUserSuppliedConnection = userSuppliedConnection != null; - final ResourceRegistry resourceRegistry = new ResourceRegistryStandardImpl( owner.getJdbcSessionContext().getEventHandler() ); + final ResourceRegistry resourceRegistry = + new ResourceRegistryStandardImpl( owner.getJdbcSessionContext().getEventHandler() ); if ( isUserSuppliedConnection ) { this.logicalConnection = new LogicalConnectionProvidedImpl( userSuppliedConnection, resourceRegistry ); } @@ -191,11 +192,7 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { @Override public void conditionallyExecuteBatch(BatchKey key) { - if ( currentBatch == null ) { - return; - } - - if ( !currentBatch.getKey().equals( key ) ) { + if ( currentBatch != null && !currentBatch.getKey().equals( key ) ) { JdbcBatchLogging.BATCH_LOGGER.debugf( "Conditionally executing batch - %s", currentBatch.getKey() ); currentBatch.execute(); } @@ -262,25 +259,25 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { @Override public void afterStatementExecution() { - final ConnectionReleaseMode connectionReleaseMode = getLogicalConnection().getConnectionHandlingMode().getReleaseMode(); + final ConnectionReleaseMode connectionReleaseMode = connectionReleaseMode(); LOG.tracev( "Starting after statement execution processing [{0}]", connectionReleaseMode ); if ( connectionReleaseMode == AFTER_STATEMENT ) { if ( ! releasesEnabled ) { LOG.debug( "Skipping aggressive release due to manual disabling" ); - return; } - if ( hasRegisteredResources() ) { + else if ( hasRegisteredResources() ) { LOG.debug( "Skipping aggressive release due to registered resources" ); - return; } - getLogicalConnection().afterStatement(); + else { + getLogicalConnection().afterStatement(); + } } } @Override public void afterTransaction() { transactionTimeOutInstant = -1; - switch ( getLogicalConnection().getConnectionHandlingMode().getReleaseMode() ) { + switch ( connectionReleaseMode() ) { case AFTER_STATEMENT: case AFTER_TRANSACTION: case BEFORE_TRANSACTION_COMPLETION: @@ -288,6 +285,10 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { } } + private ConnectionReleaseMode connectionReleaseMode() { + return getLogicalConnection().getConnectionHandlingMode().getReleaseMode(); + } + private boolean hasRegisteredResources() { return getLogicalConnection().getResourceRegistry().hasRegisteredResources(); } @@ -319,9 +320,10 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { if ( statement instanceof JdbcWrapper ) { final JdbcWrapper wrapper = (JdbcWrapper) statement; registerLastQuery( wrapper.getWrappedObject() ); - return; } - lastQuery = statement; + else { + lastQuery = statement; + } } @Override @@ -355,7 +357,6 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { releasesEnabled = false; } - @SuppressWarnings("unchecked") protected void close(Statement statement) { LOG.tracev( "Closing prepared statement [{0}]", statement ); @@ -364,38 +365,39 @@ public class JdbcCoordinatorImpl implements JdbcCoordinator { sqlExceptionHelper().logAndClearWarnings( statement ); if ( statement instanceof InvalidatableWrapper ) { + @SuppressWarnings("unchecked") final InvalidatableWrapper wrapper = (InvalidatableWrapper) statement; close( wrapper.getWrappedObject() ); wrapper.invalidate(); - return; } - - try { - // if we are unable to "clean" the prepared statement, - // we do not close it + else { try { - if ( statement.getMaxRows() != 0 ) { - statement.setMaxRows( 0 ); + // if we are unable to "clean" the prepared statement, + // we do not close it + try { + if ( statement.getMaxRows() != 0 ) { + statement.setMaxRows( 0 ); + } + if ( statement.getQueryTimeout() != 0 ) { + statement.setQueryTimeout( 0 ); + } } - if ( statement.getQueryTimeout() != 0 ) { - statement.setQueryTimeout( 0 ); + catch( SQLException sqle ) { + // there was a problem "cleaning" the prepared statement + if ( LOG.isDebugEnabled() ) { + LOG.debugf( "Exception clearing maxRows/queryTimeout [%s]", sqle.getMessage() ); + } + // EARLY EXIT!!! + return; + } + statement.close(); + if ( lastQuery == statement ) { + lastQuery = null; } } - catch( SQLException sqle ) { - // there was a problem "cleaning" the prepared statement - if ( LOG.isDebugEnabled() ) { - LOG.debugf( "Exception clearing maxRows/queryTimeout [%s]", sqle.getMessage() ); - } - // EARLY EXIT!!! - return; + catch ( Exception e ) { + LOG.debugf( "Unable to release JDBC statement [%s]", e.getMessage() ); } - statement.close(); - if ( lastQuery == statement ) { - lastQuery = null; - } - } - catch ( Exception e ) { - LOG.debugf( "Unable to release JDBC statement [%s]", e.getMessage() ); } }