From 6728afadb75a7a5077419f9d4118ec23838c941e Mon Sep 17 00:00:00 2001
From: koisyu <koisyu@toss.im>
Date: Thu, 26 May 2022 17:42:53 +0900
Subject: [PATCH] HHH-15300 - Lazy evaluation to statement.toString() when
 logging slow queries

---
 .../engine/jdbc/spi/SqlStatementLogger.java   | 17 ++++--
 .../jdbc/spi/SqlStatementLoggerTest.java      | 58 +++++++++++++++++++
 2 files changed, 70 insertions(+), 5 deletions(-)
 create mode 100644 hibernate-core/src/test/java/org/hibernate/engine/jdbc/spi/SqlStatementLoggerTest.java

diff --git a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java
index ae8f66f876..642f84b866 100644
--- a/hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java
+++ b/hibernate-core/src/main/java/org/hibernate/engine/jdbc/spi/SqlStatementLogger.java
@@ -14,6 +14,7 @@ import org.jboss.logging.Logger;
 
 import java.sql.Statement;
 import java.util.concurrent.TimeUnit;
+import java.util.function.Supplier;
 
 /**
  * Centralize logging for SQL statements.
@@ -138,10 +139,7 @@ public class SqlStatementLogger {
 	 * @param startTimeNanos Start time in nanoseconds.
 	 */
 	public void logSlowQuery(Statement statement, long startTimeNanos) {
-		if ( logSlowQuery < 1 ) {
-			return;
-		}
-		logSlowQuery( statement.toString(), startTimeNanos );
+		logSlowQuery( statement::toString, startTimeNanos );
 	}
 
 	/**
@@ -152,6 +150,15 @@ public class SqlStatementLogger {
 	 */
 	@AllowSysOut
 	public void logSlowQuery(String sql, long startTimeNanos) {
+		logSlowQuery( () -> sql, startTimeNanos );
+	}
+
+	/**
+	 * @param sqlSupplier Supplier to generate The SQL query.
+	 * @param startTimeNanos Start time in nanoseconds.
+	 */
+	@AllowSysOut
+	private void logSlowQuery(Supplier<String> sqlSupplier, long startTimeNanos) {
 		if ( logSlowQuery < 1 ) {
 			return;
 		}
@@ -162,7 +169,7 @@ public class SqlStatementLogger {
 		long queryExecutionMillis = TimeUnit.NANOSECONDS.toMillis( System.nanoTime() - startTimeNanos );
 
 		if ( queryExecutionMillis > logSlowQuery ) {
-			String logData = "SlowQuery: " + queryExecutionMillis + " milliseconds. SQL: '" + sql + "'";
+			String logData = "SlowQuery: " + queryExecutionMillis + " milliseconds. SQL: '" + sqlSupplier.get() + "'";
 			LOG_SLOW.info( logData );
 			if ( logToStdout ) {
 				System.out.println( logData );
diff --git a/hibernate-core/src/test/java/org/hibernate/engine/jdbc/spi/SqlStatementLoggerTest.java b/hibernate-core/src/test/java/org/hibernate/engine/jdbc/spi/SqlStatementLoggerTest.java
new file mode 100644
index 0000000000..5c66ea445b
--- /dev/null
+++ b/hibernate-core/src/test/java/org/hibernate/engine/jdbc/spi/SqlStatementLoggerTest.java
@@ -0,0 +1,58 @@
+package org.hibernate.engine.jdbc.spi;
+
+import java.sql.Statement;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
+
+import org.hibernate.testing.TestForIssue;
+import org.junit.jupiter.api.Test;
+
+import org.mockito.stubbing.Answer;
+
+import static org.junit.jupiter.api.Assertions.assertEquals;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+
+/**
+ * @author Kyuhee Cho
+ */
+@TestForIssue(jiraKey = "HHH-15300")
+class SqlStatementLoggerTest {
+
+	@Test
+	public void testLogSlowQueryFromStatementWhenLoggingDisabled() {
+		SqlStatementLogger sqlStatementLogger = new SqlStatementLogger( false, false, false, 0L );
+		AtomicInteger callCounterToString = new AtomicInteger();
+		Statement statement = mockStatementForCountingToString( callCounterToString );
+
+		sqlStatementLogger.logSlowQuery( statement, System.nanoTime() );
+		assertEquals( 0, callCounterToString.get() );
+	}
+
+	@Test
+	public void testLogSlowQueryFromStatementWhenLoggingEnabled() {
+		long logSlowQueryThresholdMillis = 300L;
+		SqlStatementLogger sqlStatementLogger = new SqlStatementLogger(
+				false,
+				false,
+				false,
+				logSlowQueryThresholdMillis
+		);
+		AtomicInteger callCounterToString = new AtomicInteger();
+		Statement statement = mockStatementForCountingToString( callCounterToString );
+
+		long startTimeNanos = System.nanoTime() - TimeUnit.MILLISECONDS.toNanos( logSlowQueryThresholdMillis + 1 );
+		sqlStatementLogger.logSlowQuery( statement, startTimeNanos );
+		assertEquals( 1, callCounterToString.get() );
+	}
+
+	private Statement mockStatementForCountingToString(AtomicInteger callCounter) {
+		Statement statement = mock( Statement.class );
+		when( statement.toString() ).then( (Answer<String>) invocation -> {
+			callCounter.incrementAndGet();
+			return (String) invocation.callRealMethod();
+		} );
+		return statement;
+	}
+
+}