HHH-19653 logging for JDBC fetch size and query timeout

possible mitigation for Oracle fetch size issue

Author: gavinking

hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java

@@ -152,8 +152,32 @@ public interface JdbcLogging extends BasicLogger {
 	@Message(value = "Unable to roll back isolated connection on exception ", id = 100021)
 	void unableToRollBackIsolatedConnection(@Cause Exception ignored);
 
+	@LogMessage(level = DEBUG)
+	@Message(value = "Using default JDBC fetch size: %s", id = 100022)
+	void usingFetchSize(int fetchSize);
+
+	@LogMessage(level = WARN)
+	@Message(value = "Low default JDBC fetch size: %s (consider setting 'hibernate.jdbc.fetch_size')", id = 100023)
+	void warnLowFetchSize(int fetchSize);
+
+	@LogMessage(level = TRACE)
+	@Message(value = "JDBC fetch size: %s", id = 100024)
+	void fetchSize(int fetchSize);
+
+	@LogMessage(level = DEBUG)
+	@Message(value = "Low JDBC fetch size: %s (consider setting 'hibernate.jdbc.fetch_size')", id = 100025)
+	void lowFetchSize(int fetchSize);
+
+	@LogMessage(level = TRACE)
+	@Message(value = "Setting JDBC fetch size: %s", id = 100026)
+	void settingFetchSize(int fetchSize);
+
+	@LogMessage(level = TRACE)
+	@Message(value = "Setting JDBC query timeout: %s", id = 100027)
+	void settingQueryTimeout(int timeout);
+
 	@LogMessage(level = WARN)
-	@Message(value = "Called joinTransaction() on a non-JTA EntityManager (ignoring)", id = 100025)
+	@Message(value = "Called joinTransaction() on a non-JTA EntityManager (ignoring)", id = 100030)
 	void callingJoinTransactionOnNonJtaEntityManager();
 
 	@LogMessage(level = TRACE)

hibernate-core/src/main/java/org/hibernate/engine/jdbc/env/internal/ExtractedDatabaseMetaDataImpl.java

@@ -8,6 +8,7 @@
 import java.sql.DatabaseMetaData;
 import java.sql.ResultSet;
 import java.sql.SQLException;
+import java.sql.Statement;
 import java.util.Collections;
 import java.util.List;
 import java.util.stream.Collectors;
@@ -49,7 +50,7 @@ public class ExtractedDatabaseMetaDataImpl implements ExtractedDatabaseMetaData
 	private final String url;
 	private final String driver;
 	private final boolean jdbcMetadataAccessible;
-
+	private final int defaultFetchSize;
 
 	//Lazily initialized: loading all sequence information upfront has been
 	//shown to be too slow in some cases. In this way we only load it
@@ -71,6 +72,7 @@ private ExtractedDatabaseMetaDataImpl(
 			SQLStateType sqlStateType,
 			int transactionIsolation,
 			int defaultTransactionIsolation,
+			int defaultFetchSize,
 			String url,
 			String driver,
 			boolean jdbcMetadataIsAccessible) {
@@ -88,6 +90,7 @@ private ExtractedDatabaseMetaDataImpl(
 		this.sqlStateType = sqlStateType;
 		this.transactionIsolation = transactionIsolation;
 		this.defaultTransactionIsolation = defaultTransactionIsolation;
+		this.defaultFetchSize = defaultFetchSize;
 		this.url = url;
 		this.driver = driver;
 		this.jdbcMetadataAccessible = jdbcMetadataIsAccessible;
@@ -168,6 +171,11 @@ public int getDefaultTransactionIsolation() {
 		return defaultTransactionIsolation;
 	}
 
+	@Override
+	public int getDefaultFetchSize() {
+		return defaultFetchSize;
+	}
+
 	@Override
 	public synchronized List<SequenceInformation> getSequenceInformationList() {
 		if ( jdbcMetadataAccessible ) {
@@ -211,6 +219,7 @@ public static class Builder {
 		private String driver;
 		private int defaultTransactionIsolation;
 		private int transactionIsolation;
+		private int defaultFetchSize;
 
 		public Builder(JdbcEnvironment jdbcEnvironment, boolean jdbcMetadataIsAccessible, JdbcConnectionAccess connectionAccess) {
 			this.jdbcEnvironment = jdbcEnvironment;
@@ -233,6 +242,12 @@ public Builder apply(DatabaseMetaData databaseMetaData) throws SQLException {
 			driver = databaseMetaData.getDriverName();
 			defaultTransactionIsolation = databaseMetaData.getDefaultTransactionIsolation();
 			transactionIsolation = databaseMetaData.getConnection().getTransactionIsolation();
+			try ( Statement statement = databaseMetaData.getConnection().createStatement() ) {
+				defaultFetchSize = statement.getFetchSize();
+			}
+			catch (SQLException sqle) {
+				defaultFetchSize = -1;
+			}
 			return this;
 		}
 
@@ -302,6 +317,7 @@ public ExtractedDatabaseMetaDataImpl build() {
 					sqlStateType,
 					transactionIsolation,
 					defaultTransactionIsolation,
+					defaultFetchSize,
 					url,
 					driver,
 					jdbcMetadataIsAccessible

hibernate-core/src/main/java/org/hibernate/engine/jdbc/env/internal/JdbcEnvironmentImpl.java

@@ -10,6 +10,7 @@
 import org.hibernate.boot.model.naming.Identifier;
 import org.hibernate.boot.registry.selector.spi.StrategySelector;
 import org.hibernate.cfg.AvailableSettings;
+import org.hibernate.cfg.JdbcSettings;
 import org.hibernate.dialect.Dialect;
 import org.hibernate.engine.config.spi.ConfigurationService;
 import org.hibernate.engine.config.spi.StandardConverters;
@@ -38,6 +39,7 @@
 import static org.hibernate.cfg.MappingSettings.DEFAULT_CATALOG;
 import static org.hibernate.cfg.MappingSettings.DEFAULT_SCHEMA;
 import static org.hibernate.engine.config.spi.StandardConverters.STRING;
+import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER;
 import static org.hibernate.engine.jdbc.env.internal.LobCreatorBuilderImpl.makeLobCreatorBuilder;
 
 /**
@@ -105,6 +107,8 @@ public JdbcEnvironmentImpl(final ServiceRegistryImplementor serviceRegistry, fin
 				new QualifiedObjectNameFormatterStandardImpl( nameQualifierSupport, dialect.getCatalogSeparator() );
 
 		lobCreatorBuilder = makeLobCreatorBuilder( dialect );
+
+		logJdbcFetchSize( extractedMetaDataSupport.getDefaultFetchSize(), cfgService );
 	}
 
 	private static ConfigurationService configurationService(ServiceRegistryImplementor serviceRegistry) {
@@ -317,6 +321,8 @@ public JdbcEnvironmentImpl(
 				new QualifiedObjectNameFormatterStandardImpl( nameQualifierSupport, databaseMetaData );
 
 		lobCreatorBuilder = makeLobCreatorBuilder( dialect, cfgService.getSettings(), databaseMetaData.getConnection() );
+
+		logJdbcFetchSize( extractedMetaDataSupport.getDefaultFetchSize(), cfgService );
 	}
 
 	private static IdentifierHelper identifierHelper(
@@ -420,4 +426,14 @@ public LobCreatorBuilder getLobCreatorBuilder() {
 		return lobCreatorBuilder;
 	}
 
+	private static void logJdbcFetchSize(int defaultFetchSize, ConfigurationService cfgService) {
+		if ( !cfgService.getSettings().containsKey( JdbcSettings.STATEMENT_FETCH_SIZE ) ) {
+			if ( defaultFetchSize > 0 && defaultFetchSize < 100 ) {
+				JDBC_MESSAGE_LOGGER.warnLowFetchSize( defaultFetchSize );
+			}
+			else {
+				JDBC_MESSAGE_LOGGER.usingFetchSize( defaultFetchSize );
+			}
+		}
+	}
 }

hibernate-core/src/main/java/org/hibernate/engine/jdbc/env/spi/ExtractedDatabaseMetaData.java

@@ -150,6 +150,11 @@ public interface ExtractedDatabaseMetaData {
 	 */
 	int getDefaultTransactionIsolation();
 
+	/**
+	 * Retrieve the default JDBC {@link java.sql.Statement#getFetchSize fetch size}.
+	 */
+	int getDefaultFetchSize();
+
 	/**
 	 * Retrieve the list of {@code SequenceInformation} objects which describe the underlying database sequences.
 	 *

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

@@ -25,6 +25,8 @@
 
 import org.checkerframework.checker.nullness.qual.Nullable;
 
+import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER;
+
 /**
  * Standard implementation of {@link StatementPreparer}.
  *
@@ -141,7 +143,7 @@ public PreparedStatement prepareQueryStatement(
 		final int resultSetType;
 		if ( scrollMode != null && scrollMode != ScrollMode.FORWARD_ONLY ) {
 			if ( !settings().isScrollableResultSetsEnabled() ) {
-				throw new AssertionFailure("scrollable result sets are not enabled");
+				throw new AssertionFailure( "Scrollable result sets are not enabled" );
 			}
 			resultSetType = scrollMode.toResultSetType();
 		}
@@ -224,8 +226,21 @@ public void postProcess(PreparedStatement preparedStatement) throws SQLException
 	}
 
 	private void setStatementFetchSize(PreparedStatement statement) throws SQLException {
-		if ( settings().getFetchSizeOrNull() != null ) {
-			statement.setFetchSize( settings().getFetchSizeOrNull() );
+		final Integer fetchSize = settings().getFetchSizeOrNull();
+		if ( fetchSize != null ) {
+			JDBC_MESSAGE_LOGGER.settingFetchSize( fetchSize );
+			statement.setFetchSize( fetchSize );
+		}
+		else {
+			if ( JDBC_MESSAGE_LOGGER.isDebugEnabled() ) {
+				final int defaultFetchSize = statement.getFetchSize();
+				if ( defaultFetchSize > 0 && defaultFetchSize < 100 ) {
+					JDBC_MESSAGE_LOGGER.lowFetchSize( defaultFetchSize );
+				}
+			}
+			else if ( JDBC_MESSAGE_LOGGER.isTraceEnabled() ) {
+				JDBC_MESSAGE_LOGGER.fetchSize( statement.getFetchSize() );
+			}
 		}
 	}
 

hibernate-core/src/main/java/org/hibernate/sql/results/jdbc/internal/DeferredResultSetAccess.java

@@ -36,6 +36,7 @@
 import org.hibernate.sql.exec.spi.JdbcSelectExecutor;
 
 import static java.util.Collections.emptyMap;
+import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER;
 
 /**
  * @author Steve Ebersole
@@ -241,11 +242,15 @@ private void setQueryOptions(PreparedStatement preparedStatement) throws SQLExce
 		final QueryOptions queryOptions = executionContext.getQueryOptions();
 		// set options
 		if ( queryOptions != null ) {
-			if ( queryOptions.getFetchSize() != null ) {
-				preparedStatement.setFetchSize( queryOptions.getFetchSize() );
+			final Integer fetchSize = queryOptions.getFetchSize();
+			if ( fetchSize != null ) {
+				JDBC_MESSAGE_LOGGER.settingFetchSize( fetchSize );
+				preparedStatement.setFetchSize( fetchSize );
 			}
-			if ( queryOptions.getTimeout() != null ) {
-				preparedStatement.setQueryTimeout( queryOptions.getTimeout() );
+			final Integer timeout = queryOptions.getTimeout();
+			if ( timeout != null ) {
+				JDBC_MESSAGE_LOGGER.settingQueryTimeout( timeout );
+				preparedStatement.setQueryTimeout( timeout );
 			}
 		}
 	}