HHH-16909 expose slow queries via Statistics API

hibernate-core/src/main/java/org/hibernate/cfg/AvailableSettings.java

@@ -2273,6 +2273,8 @@ public interface AvailableSettings {
 	 * time to execute will be logged.
 	 * <p>
 	 * A value of {@code 0}, the default, disables logging of "slow" queries.
+	 *
+	 * @see org.hibernate.stat.Statistics#getSlowQueries()
 	 */
 	String LOG_SLOW_QUERY = "hibernate.log_slow_query";
 
@@ -2686,6 +2688,8 @@ public interface AvailableSettings {
 	 * The default value is {@value org.hibernate.stat.Statistics#DEFAULT_QUERY_STATISTICS_MAX_SIZE}.
 	 *
 	 * @since 5.4
+	 *
+	 * @see org.hibernate.stat.Statistics#getQueries()
 	 */
 	String QUERY_STATISTICS_MAX_SIZE = "hibernate.statistics.query_max_size";
 

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

@@ -18,6 +18,7 @@
 import org.hibernate.engine.jdbc.spi.ResultSetReturn;
 import org.hibernate.engine.jdbc.spi.SqlExceptionHelper;
 import org.hibernate.engine.jdbc.spi.SqlStatementLogger;
+import org.hibernate.resource.jdbc.spi.JdbcSessionContext;
 
 /**
  * Standard implementation of the ResultSetReturn contract
@@ -58,7 +59,7 @@ public ResultSet extract(PreparedStatement statement) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( statement, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( statement, executeStartNanos, context() );
 			}
 			postExtract( rs, statement );
 			return rs;
@@ -83,7 +84,7 @@ public ResultSet extract(PreparedStatement statement, String sql) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( sql, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( sql, executeStartNanos, context() );
 			}
 			postExtract( rs, statement );
 			return rs;
@@ -93,6 +94,10 @@ public ResultSet extract(PreparedStatement statement, String sql) {
 		}
 	}
 
+	private JdbcSessionContext context() {
+		return jdbcCoordinator.getJdbcSessionOwner().getJdbcSessionContext();
+	}
+
 	private void jdbcExecuteStatementEnd() {
 		jdbcCoordinator.getJdbcSessionOwner().getJdbcSessionContext().getObserver().jdbcExecuteStatementEnd();
 	}
@@ -116,7 +121,7 @@ public ResultSet extract(CallableStatement callableStatement) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( callableStatement, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( callableStatement, executeStartNanos, context() );
 			}
 			postExtract( rs, callableStatement );
 			return rs;
@@ -141,7 +146,7 @@ public ResultSet extract(Statement statement, String sql) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( sql, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( sql, executeStartNanos, context() );
 			}
 			postExtract( rs, statement );
 			return rs;
@@ -171,7 +176,7 @@ public ResultSet execute(PreparedStatement statement) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( statement, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( statement, executeStartNanos, context() );
 			}
 			postExtract( rs, statement );
 			return rs;
@@ -201,7 +206,7 @@ public ResultSet execute(PreparedStatement statement, String sql) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( sql, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( sql, executeStartNanos, context() );
 			}
 			postExtract( rs, statement );
 			return rs;
@@ -231,7 +236,7 @@ public ResultSet execute(Statement statement, String sql) {
 			}
 			finally {
 				jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( sql, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( sql, executeStartNanos, context() );
 			}
 			postExtract( rs, statement );
 			return rs;
@@ -258,7 +263,7 @@ public int executeUpdate(PreparedStatement statement) {
 		}
 		finally {
 			jdbcExecuteStatementEnd();
-			sqlStatementLogger.logSlowQuery( statement, executeStartNanos );
+			sqlStatementLogger.logSlowQuery( statement, executeStartNanos, context() );
 		}
 	}
 
@@ -279,7 +284,7 @@ public int executeUpdate(PreparedStatement statement, String sql) {
 		}
 		finally {
 			jdbcExecuteStatementEnd();
-			sqlStatementLogger.logSlowQuery( sql, executeStartNanos );
+			sqlStatementLogger.logSlowQuery( sql, executeStartNanos, context() );
 		}
 	}
 
@@ -299,7 +304,7 @@ public int executeUpdate(Statement statement, String sql) {
 		}
 		finally {
 			jdbcExecuteStatementEnd();
-			sqlStatementLogger.logSlowQuery( sql, executeStartNanos );
+			sqlStatementLogger.logSlowQuery( sql, executeStartNanos, context() );
 		}
 	}
 

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

@@ -10,8 +10,10 @@
 import org.hibernate.engine.jdbc.internal.Formatter;
 import org.hibernate.internal.CoreLogging;
 import org.hibernate.internal.build.AllowSysOut;
+import org.hibernate.resource.jdbc.spi.JdbcSessionContext;
 import org.hibernate.service.Service;
 
+import org.hibernate.stat.spi.StatisticsImplementor;
 import org.jboss.logging.Logger;
 
 import java.sql.Statement;
@@ -27,8 +29,8 @@ public class SqlStatementLogger implements Service {
 	private static final Logger LOG = CoreLogging.logger( "org.hibernate.SQL" );
 	private static final Logger LOG_SLOW = CoreLogging.logger( "org.hibernate.SQL_SLOW" );
 
-	private boolean logToStdout;
+	private final boolean logToStdout;
-	private boolean format;
+	private final boolean format;
 	private final boolean highlight;
 
 	/**
@@ -46,7 +48,7 @@ public SqlStatementLogger() {
 	/**
 	 * Constructs a new {@code SqlStatementLogger} instance.
 	 *
-	 * @param logToStdout Should we log to STDOUT in addition to our internal logger.
+	 * @param logToStdout Should we log to STDOUT in addition to our internal logger?
 	 * @param format Should we format the statements in the console and log
 	 */
 	public SqlStatementLogger(boolean logToStdout, boolean format) {
@@ -56,7 +58,7 @@ public SqlStatementLogger(boolean logToStdout, boolean format) {
 	/**
 	 * Constructs a new {@code SqlStatementLogger} instance.
 	 *
-	 * @param logToStdout Should we log to STDOUT in addition to our internal logger.
+	 * @param logToStdout Should we log to STDOUT in addition to our internal logger?
 	 * @param format Should we format the statements in the console and log
 	 * @param highlight Should we highlight the statements in the console
 	 */
@@ -67,7 +69,7 @@ public SqlStatementLogger(boolean logToStdout, boolean format, boolean highlight
 	/**
 	 * Constructs a new {@code SqlStatementLogger} instance.
 	 *
-	 * @param logToStdout Should we log to STDOUT in addition to our internal logger.
+	 * @param logToStdout Should we log to STDOUT in addition to our internal logger?
 	 * @param format Should we format the statements in the console and log
 	 * @param highlight Should we highlight the statements in the console
 	 * @param logSlowQuery Should we logs query which executed slower than specified milliseconds. 0 - disabled.
@@ -143,8 +145,8 @@ public void logStatement(String statement, Formatter formatter) {
 	 * @param statement SQL statement.
 	 * @param startTimeNanos Start time in nanoseconds.
 	 */
-	public void logSlowQuery(Statement statement, long startTimeNanos) {
+	public void logSlowQuery(Statement statement, long startTimeNanos, JdbcSessionContext context) {
-		logSlowQuery( statement::toString, startTimeNanos );
+		logSlowQuery( statement::toString, startTimeNanos, context );
 	}
 
 	/**
@@ -154,8 +156,8 @@ public void logSlowQuery(Statement statement, long startTimeNanos) {
 	 * @param startTimeNanos Start time in nanoseconds.
 	 */
 	@AllowSysOut
-	public void logSlowQuery(String sql, long startTimeNanos) {
+	public void logSlowQuery(String sql, long startTimeNanos, JdbcSessionContext context) {
-		logSlowQuery( () -> sql, startTimeNanos );
+		logSlowQuery( sql::toString, startTimeNanos, context );
 	}
 
 	/**
@@ -163,7 +165,7 @@ public void logSlowQuery(String sql, long startTimeNanos) {
 	 * @param startTimeNanos Start time in nanoseconds.
 	 */
 	@AllowSysOut
-	private void logSlowQuery(Supplier<String> sqlSupplier, long startTimeNanos) {
+	private void logSlowQuery(Supplier<String> sqlSupplier, long startTimeNanos, JdbcSessionContext context) {
 		if ( logSlowQuery < 1 ) {
 			return;
 		}
@@ -174,11 +176,18 @@ private void logSlowQuery(Supplier<String> sqlSupplier, long startTimeNanos) {
 		long queryExecutionMillis = TimeUnit.NANOSECONDS.toMillis( System.nanoTime() - startTimeNanos );
 
 		if ( queryExecutionMillis > logSlowQuery ) {
-			String logData = "SlowQuery: " + queryExecutionMillis + " milliseconds. SQL: '" + sqlSupplier.get() + "'";
+			final String sql = sqlSupplier.get();
+			final String logData = "Slow query took " + queryExecutionMillis + " milliseconds [" + sql + "]";
 			LOG_SLOW.info( logData );
 			if ( logToStdout ) {
 				System.out.println( logData );
 			}
+			if ( context != null ) {
+				final StatisticsImplementor statisticsImplementor = context.getStatistics();
+				if ( statisticsImplementor != null && statisticsImplementor.isStatisticsEnabled() ) {
+					statisticsImplementor.slowQuery( sql, queryExecutionMillis );
+				}
+			}
 		}
 	}
 }

hibernate-core/src/main/java/org/hibernate/internal/JdbcSessionContextImpl.java

@@ -16,6 +16,7 @@
 import org.hibernate.resource.jdbc.spi.PhysicalConnectionHandlingMode;
 import org.hibernate.resource.jdbc.spi.StatementInspector;
 import org.hibernate.service.ServiceRegistry;
+import org.hibernate.stat.spi.StatisticsImplementor;
 
 /**
  * @author Steve Ebersole
@@ -131,4 +132,9 @@ public BatchBuilder getBatchBuilder() {
 	public boolean isActive() {
 		return !sessionFactory.isClosed();
 	}
+
+	@Override
+	public StatisticsImplementor getStatistics() {
+		return sessionFactory.getStatistics();
+	}
 }

hibernate-core/src/main/java/org/hibernate/resource/jdbc/spi/JdbcSessionContext.java

@@ -11,6 +11,7 @@
 import org.hibernate.engine.spi.SessionFactoryImplementor;
 import org.hibernate.jpa.spi.JpaCompliance;
 import org.hibernate.service.ServiceRegistry;
+import org.hibernate.stat.spi.StatisticsImplementor;
 
 /**
  * Provides the "JDBC session" with contextual information it needs during its lifecycle.
@@ -60,6 +61,8 @@ public interface JdbcSessionContext {
 
 	JpaCompliance getJpaCompliance();
 
+	StatisticsImplementor getStatistics();
+
 	/**
 	 * @deprecated since {@link JdbcObserver} is deprecated
 	 */

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

@@ -24,6 +24,7 @@
 import org.hibernate.internal.CoreMessageLogger;
 import org.hibernate.query.spi.Limit;
 import org.hibernate.query.spi.QueryOptions;
+import org.hibernate.resource.jdbc.spi.JdbcSessionContext;
 import org.hibernate.resource.jdbc.spi.LogicalConnectionImplementor;
 import org.hibernate.sql.exec.spi.ExecutionContext;
 import org.hibernate.sql.exec.spi.JdbcLockStrategy;
@@ -240,7 +241,7 @@ private void executeQuery() {
 			}
 			finally {
 				eventListenerManager.jdbcExecuteStatementEnd();
-				sqlStatementLogger.logSlowQuery( preparedStatement, executeStartNanos );
+				sqlStatementLogger.logSlowQuery( preparedStatement, executeStartNanos, context() );
 			}
 
 			skipRows( resultSet );
@@ -264,6 +265,10 @@ private void executeQuery() {
 		}
 	}
 
+	private JdbcSessionContext context() {
+		return executionContext.getSession().getJdbcCoordinator().getJdbcSessionOwner().getJdbcSessionContext();
+	}
+
 	protected void skipRows(ResultSet resultSet) throws SQLException {
 		// For dialects that don't support an offset clause
 		final int rowsToSkip;

hibernate-core/src/main/java/org/hibernate/stat/Statistics.java

@@ -7,6 +7,7 @@
 package org.hibernate.stat;
 
 import java.time.Instant;
+import java.util.Map;
 
 import org.checkerframework.checker.nullness.qual.Nullable;
 
@@ -326,9 +327,22 @@ public interface Statistics {
 	 * The maximum number of queries tracked by the Hibernate statistics
 	 * is determined by the configuration property
 	 * {@value org.hibernate.cfg.AvailableSettings#QUERY_STATISTICS_MAX_SIZE}.
+	 *
+	 * @see org.hibernate.cfg.AvailableSettings#QUERY_STATISTICS_MAX_SIZE
 	 */
 	String[] getQueries();
 
+	/**
+	 * If {@value org.hibernate.cfg.AvailableSettings#LOG_SLOW_QUERY}
+	 * is enabled, a map from the SQL query to the maximum execution time
+	 * in milliseconds.
+	 *
+	 * @since 6.3
+	 *
+	 * @see org.hibernate.cfg.AvailableSettings#LOG_SLOW_QUERY
+	 */
+	Map<String,Long> getSlowQueries();
+
 	/**
 	 * The names of all entities.
 	 */

hibernate-core/src/main/java/org/hibernate/stat/internal/StatisticsImpl.java

@@ -9,7 +9,9 @@
 import java.time.Instant;
 import java.util.ArrayList;
 import java.util.List;
+import java.util.Map;
 import java.util.Objects;
+import java.util.concurrent.ConcurrentHashMap;
 import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.atomic.LongAdder;
 import java.util.function.Function;
@@ -120,6 +122,11 @@ public class StatisticsImpl implements StatisticsImplementor, Service {
 	 */
 	private final StatsNamedContainer<CacheRegionStatisticsImpl> l2CacheStatsMap = new StatsNamedContainer<>();
 
+	/**
+	 * Keyed by query SQL
+	 */
+	private final Map<String, Long> slowQueries = new ConcurrentHashMap<>();
+
 	public StatisticsImpl(SessionFactoryImplementor sessionFactory) {
 		Objects.requireNonNull( sessionFactory );
 		SessionFactoryOptions sessionFactoryOptions = sessionFactory.getSessionFactoryOptions();
@@ -1022,4 +1029,14 @@ private CacheRegionStatisticsImpl instantiateCacheRegionStatsForQueryResults(fin
 
 		return new CacheRegionStatisticsImpl( region );
 	}
+
+	@Override
+	public Map<String, Long> getSlowQueries() {
+		return slowQueries;
+	}
+
+	@Override
+	public void slowQuery(String sql, long executionTime) {
+		slowQueries.merge( sql, executionTime, Math::max );
+	}
 }

hibernate-core/src/main/java/org/hibernate/stat/internal/StatsNamedContainer.java

@@ -15,14 +15,15 @@
 
 import org.checkerframework.checker.nullness.qual.Nullable;
 
+import static org.hibernate.internal.util.collections.BoundedConcurrentHashMap.Eviction.LRU;
+
 /**
  * Decorates a ConcurrentHashMap implementation to make sure the methods are being
- * used correctly for the purpose of Hibernate's statistics.
+ * used correctly for the purpose of Hibernate's statistics. In particular, we do
- * In particular, we do like the semantics of ConcurrentHashMap#computeIfAbsent
+ * like the semantics of {@link ConcurrentHashMap#computeIfAbsent} but not its
- * but not how it performs.
+ * performance.
- * See also:
+ * <p>
- *  - http://jsr166-concurrency.10961.n7.nabble.com/Re-ConcurrentHashMap-computeIfAbsent-td11687.html
+ * See <a href="https://hibernate.atlassian.net/browse/HHH-13527">HHH-13527</a>.
- *  - https://hibernate.atlassian.net/browse/HHH-13527
  *
  * @author Sanne Grinovero
  */
@@ -35,7 +36,7 @@ public final class StatsNamedContainer<V> {
 	 * Creates a bounded container - based on BoundedConcurrentHashMap
 	 */
 	public StatsNamedContainer(int capacity, int concurrencyLevel) {
-		this.map = new BoundedConcurrentHashMap<>( capacity, concurrencyLevel, BoundedConcurrentHashMap.Eviction.LRU );
+		this.map = new BoundedConcurrentHashMap<>( capacity, concurrencyLevel, LRU );
 	}
 
 	/**
@@ -61,10 +62,11 @@ public String[] keysAsArray() {
 	/**
 	 * Similar semantics as you'd get by invoking {@link ConcurrentMap#computeIfAbsent(Object, Function)},
 	 * but we check for the key existence first.
-	 * This is technically a redundant check, but it has been shown to perform better when the key existing is very likely,
+	 * This is technically a redundant check, but it has been shown to perform better
-	 * as in our case.
+	 * when the key existing is very likely, as in our case.
-	 * Most notably, the ConcurrentHashMap implementation might block other accesses for the sake of making
+	 * Most notably, the ConcurrentHashMap implementation might block other accesses
-	 * sure the function is invoked at most once: we don't need this guarantee, and prefer to reduce risk of blocking.
+	 * for the sake of making sure the function is invoked at most once: we don't need
+	 * this guarantee, and prefer to reduce risk of blocking.
 	 */
 	@SuppressWarnings("unchecked")
 	public @Nullable V getOrCompute(final String key, final Function<String, V> function) {

hibernate-core/src/main/java/org/hibernate/stat/spi/StatisticsImplementor.java

@@ -10,6 +10,10 @@
 import org.hibernate.service.Service;
 import org.hibernate.stat.Statistics;
 
+import java.util.Map;
+
+import static java.util.Collections.emptyMap;
+
 /**
  * A service SPI for collecting statistics about various events that occur at runtime.
  *
@@ -274,4 +278,17 @@ default void queryPlanCacheMiss(String query) {
 	default void queryCompiled(String hql, long microseconds) {
 		//For backward compatibility
 	}
+
+	/**
+	 * Register the execution of a slow SQL query.
+	 */
+	default void slowQuery(String sql, long executionTime) {
+		//For backward compatibility
+	}
+
+	@Override
+	default Map<String, Long> getSlowQueries() {
+		//For backward compatibility
+		return emptyMap();
+	}
 }

hibernate-core/src/test/java/org/hibernate/engine/jdbc/spi/SqlStatementLoggerTest.java

@@ -25,7 +25,7 @@ public void testLogSlowQueryFromStatementWhenLoggingDisabled() {
 		AtomicInteger callCounterToString = new AtomicInteger();
 		Statement statement = mockStatementForCountingToString( callCounterToString );
 
-		sqlStatementLogger.logSlowQuery( statement, System.nanoTime() );
+		sqlStatementLogger.logSlowQuery( statement, System.nanoTime(), null );
 		assertEquals( 0, callCounterToString.get() );
 	}
 
@@ -42,7 +42,7 @@ public void testLogSlowQueryFromStatementWhenLoggingEnabled() {
 		Statement statement = mockStatementForCountingToString( callCounterToString );
 
 		long startTimeNanos = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos( logSlowQueryThresholdMillis + 1 );
-		sqlStatementLogger.logSlowQuery( statement, startTimeNanos );
+		sqlStatementLogger.logSlowQuery( statement, startTimeNanos, null );
 		assertEquals( 1, callCounterToString.get() );
 	}