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

HHH-13249 Introduce an option to Log slow queries instead of all queries

This commit is contained in:
Batbileg Dorj 2019-08-03 00:37:52 -05:00 committed by Sanne Grinovero
parent 618d186cb2
commit d9e16fe8ca
4 changed files with 105 additions and 1 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

5
hibernate-core/src/main/java/org/hibernate/cfg/AvailableSettings.java
View File

@ -1726,6 +1726,11 @@ public interface AvailableSettings extends org.hibernate.jpa.AvailableSettings {
*/
String LOG_SESSION_METRICS = "hibernate.session.events.log";
/**
* Setting that logs query which executed slower than specified milliseconds. Default is 0 (disabled).
*/
String LOG_SLOW_QUERY = "hibernate.session.events.log.LOG_QUERIES_SLOWER_THAN_MS";
/**
* Defines a default {@link org.hibernate.SessionEventListener} to be applied to opened Sessions.
*/

3
hibernate-core/src/main/java/org/hibernate/engine/jdbc/internal/JdbcServicesImpl.java
View File

@ -55,8 +55,9 @@ public class JdbcServicesImpl implements JdbcServices, ServiceRegistryAwareServi
final boolean showSQL = ConfigurationHelper.getBoolean( Environment.SHOW_SQL, configValues, false );
final boolean formatSQL = ConfigurationHelper.getBoolean( Environment.FORMAT_SQL, configValues, false );
final long logSlowQuery = ConfigurationHelper.getLong( Environment.LOG_SLOW_QUERY, configValues, 0 );
this.sqlStatementLogger = new SqlStatementLogger( showSQL, formatSQL );
this.sqlStatementLogger = new SqlStatementLogger( showSQL, formatSQL, logSlowQuery );
resultSetWrapper = new ResultSetWrapperImpl( serviceRegistry );
}

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

@ -53,6 +53,10 @@ public class ResultSetReturnImpl implements ResultSetReturn {
@Override
public ResultSet extract(PreparedStatement statement) {
// IMPL NOTE : SQL logged by caller
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
final ResultSet rs;
try {
@ -61,6 +65,7 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( statement, executeStart );
}
postExtract( rs, statement );
return rs;
@ -81,6 +86,10 @@ public class ResultSetReturnImpl implements ResultSetReturn {
@Override
public ResultSet extract(CallableStatement callableStatement) {
// IMPL NOTE : SQL logged by caller
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
final ResultSet rs;
try {
@ -89,6 +98,7 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( callableStatement, executeStart );
}
postExtract( rs, callableStatement );
return rs;
@ -101,6 +111,10 @@ public class ResultSetReturnImpl implements ResultSetReturn {
@Override
public ResultSet extract(Statement statement, String sql) {
sqlStatementLogger.logStatement( sql );
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
final ResultSet rs;
try {
@ -109,6 +123,7 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( sql, executeStart );
}
postExtract( rs, statement );
return rs;
@ -121,6 +136,10 @@ public class ResultSetReturnImpl implements ResultSetReturn {
@Override
public ResultSet execute(PreparedStatement statement) {
// sql logged by StatementPreparerImpl
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
final ResultSet rs;
try {
@ -134,6 +153,7 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( statement, executeStart );
}
postExtract( rs, statement );
return rs;
@ -146,6 +166,10 @@ public class ResultSetReturnImpl implements ResultSetReturn {
@Override
public ResultSet execute(Statement statement, String sql) {
sqlStatementLogger.logStatement( sql );
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
final ResultSet rs;
try {
@ -159,6 +183,7 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( statement, executeStart );
}
postExtract( rs, statement );
return rs;
@ -170,6 +195,10 @@ public class ResultSetReturnImpl implements ResultSetReturn {
@Override
public int executeUpdate(PreparedStatement statement) {
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
jdbcExecuteStatementStart();
return statement.executeUpdate();
@ -179,12 +208,17 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( statement, executeStart );
}
}
@Override
public int executeUpdate(Statement statement, String sql) {
sqlStatementLogger.logStatement( sql );
long executeStart = 0;
if ( this.sqlStatementLogger.getLogSlowQuery() > 0 ) {
executeStart = System.currentTimeMillis();
}
try {
jdbcExecuteStatementStart();
return statement.executeUpdate( sql );
@ -194,6 +228,7 @@ public class ResultSetReturnImpl implements ResultSetReturn {
}
finally {
jdbcExecuteStatementEnd();
sqlStatementLogger.logSlowQuery( statement, executeStart );
}
}

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

@ -6,6 +6,8 @@
*/
package org.hibernate.engine.jdbc.spi;
import java.sql.Statement;
import org.hibernate.engine.jdbc.internal.FormatStyle;
import org.hibernate.engine.jdbc.internal.Formatter;
import org.hibernate.internal.CoreLogging;
@ -20,10 +22,16 @@ import org.jboss.logging.Logger;
*/
public class SqlStatementLogger {
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 boolean format;
/**
* Configuration value that indicates slow query. (In milliseconds) 0 - disabled.
*/
private final long logSlowQuery;
/**
* Constructs a new SqlStatementLogger instance.
*/
@ -38,8 +46,20 @@ public class SqlStatementLogger {
* @param format Should we format the statements prior to logging
*/
public SqlStatementLogger(boolean logToStdout, boolean format) {
this( logToStdout, format, 0 );
}
/**
* Constructs a new SqlStatementLogger instance.
*
* @param logToStdout Should we log to STDOUT in addition to our internal logger.
* @param format Should we format the statements prior to logging
* @param logSlowQuery Should we logs query which executed slower than specified milliseconds. 0 - disabled.
*/
public SqlStatementLogger(boolean logToStdout, boolean format, long logSlowQuery) {
this.logToStdout = logToStdout;
this.format = format;
this.logSlowQuery = logSlowQuery;
}
/**
@ -77,6 +97,10 @@ public class SqlStatementLogger {
this.format = format;
}
public long getLogSlowQuery() {
return logSlowQuery;
}
/**
* Log a SQL statement string.
*
@ -105,4 +129,43 @@ public class SqlStatementLogger {
System.out.println( "Hibernate: " + statement );
}
}
/**
* Log a slow SQL query
*
* @param statement SQL statement.
* @param startTime Start time in milliseconds.
*/
public void logSlowQuery(Statement statement, long startTime) {
if ( logSlowQuery < 1 ) {
return;
}
logSlowQuery( statement.toString(), startTime );
}
/**
* Log a slow SQL query
*
* @param sql The SQL query.
* @param startTime Start time in milliseconds.
*/
@AllowSysOut
public void logSlowQuery(String sql, long startTime) {
if ( logSlowQuery < 1 ) {
return;
}
assert startTime > 0 : "startTime is invalid!";
long spent = System.currentTimeMillis() - startTime;
assert spent >= 0 : "startTime is invalid!";
if ( spent > logSlowQuery ) {
String logData = "SlowQuery: " + spent + " milliseconds. SQL: '" + sql + "'";
LOG_SLOW.info( logData );
if ( logToStdout ) {
System.out.println( logData );
}
}
}
}