Hibernate
/
hibernate-orm
mirror of https://github.com/hibernate/hibernate-orm
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

HHH-15300 - Lazy evaluation to statement.toString() when logging slow queries

This commit is contained in:
koisyu 2022-05-26 17:42:53 +09:00 committed by Steve Ebersole
parent 3635e4e935
commit 3d893712e6
2 changed files with 70 additions and 5 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

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

@ -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 );

58
hibernate-core/src/test/java/org/hibernate/engine/jdbc/spi/SqlStatementLoggerTest.java Normal file
View File

@ -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;
}
}