From 8301cb634ebec8a4ad0dbc2ce1954cfbdc1204d9 Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Tue, 3 Oct 2017 15:04:30 +1300 Subject: [PATCH] #1027 - ENH: Add a Slow query event listener ... to log or listen to queries that exceed some defined execution time --- .../java/io/ebean/config/ServerConfig.java | 39 ++++++++++++ .../java/io/ebean/config/SlowQueryEvent.java | 59 +++++++++++++++++++ .../io/ebean/config/SlowQueryListener.java | 13 ++++ .../io/ebeaninternal/api/SpiEbeanServer.java | 5 ++ .../server/core/DefaultServer.java | 18 +++++- .../server/core/DefaultSlowQueryListener.java | 26 ++++++++ .../server/core/InternalConfiguration.java | 27 +++++++++ .../server/core/OrmQueryRequest.java | 7 +++ .../io/ebeaninternal/server/query/CQuery.java | 21 +++++-- .../query/CQueryFetchSingleAttribute.java | 9 +-- .../server/query/CQueryIteratorSimple.java | 2 +- .../query/CQueryIteratorWithBuffer.java | 2 +- .../server/query/CQueryRowCount.java | 9 +-- .../server/query/CQueryUpdate.java | 8 +-- .../ebeaninternal/api/TDSpiEbeanServer.java | 5 ++ 15 files changed, 224 insertions(+), 26 deletions(-) create mode 100644 src/main/java/io/ebean/config/SlowQueryEvent.java create mode 100644 src/main/java/io/ebean/config/SlowQueryListener.java create mode 100644 src/main/java/io/ebeaninternal/server/core/DefaultSlowQueryListener.java diff --git a/src/main/java/io/ebean/config/ServerConfig.java b/src/main/java/io/ebean/config/ServerConfig.java index 94add84eb..5462fbabb 100644 --- a/src/main/java/io/ebean/config/ServerConfig.java +++ b/src/main/java/io/ebean/config/ServerConfig.java @@ -439,6 +439,16 @@ public class ServerConfig { */ private boolean disableL2Cache; + /** + * The time in millis used to determine when a query is alerted for being slow. + */ + private long slowQueryMillis; + + /** + * The listener for processing slow query events. + */ + private SlowQueryListener slowQueryListener; + /** * Construct a Server Configuration for programmatically creating an EbeanServer. */ @@ -446,6 +456,34 @@ public class ServerConfig { } + /** + * Return the slow query time in millis. + */ + public long getSlowQueryMillis() { + return slowQueryMillis; + } + + /** + * Set the slow query time in millis. + */ + public void setSlowQueryMillis(long slowQueryMillis) { + this.slowQueryMillis = slowQueryMillis; + } + + /** + * Return the slow query event listener. + */ + public SlowQueryListener getSlowQueryListener() { + return slowQueryListener; + } + + /** + * Set the slow query event listener. + */ + public void setSlowQueryListener(SlowQueryListener slowQueryListener) { + this.slowQueryListener = slowQueryListener; + } + /** * Put a service object into configuration such that it can be passed to a plugin. *

@@ -2534,6 +2572,7 @@ public class ServerConfig { dbTypeConfig.setGeometrySRID(srid); } + slowQueryMillis = p.getLong("slowQueryMillis", slowQueryMillis); docStoreOnly = p.getBoolean("docStoreOnly", docStoreOnly); disableL2Cache = p.getBoolean("disableL2Cache", disableL2Cache); explicitTransactionBeginMode = p.getBoolean("explicitTransactionBeginMode", explicitTransactionBeginMode); diff --git a/src/main/java/io/ebean/config/SlowQueryEvent.java b/src/main/java/io/ebean/config/SlowQueryEvent.java new file mode 100644 index 000000000..6afd71502 --- /dev/null +++ b/src/main/java/io/ebean/config/SlowQueryEvent.java @@ -0,0 +1,59 @@ +package io.ebean.config; + +import io.ebean.bean.ObjectGraphNode; + +/** + * Slow query event. + */ +public class SlowQueryEvent { + + private final String sql; + + private final long timeMillis; + + private final int rowCount; + + private final ObjectGraphNode originNode; + + /** + * Construct with the SQL and execution time in millis. + */ + public SlowQueryEvent(String sql, long timeMillis, int rowCount, ObjectGraphNode originNode) { + this.sql = sql; + this.timeMillis = timeMillis; + this.rowCount = rowCount; + this.originNode = originNode; + } + + /** + * Return the SQL for the slow query. + */ + public String getSql() { + return sql; + } + + /** + * Return the execution time in millis. + */ + public long getTimeMillis() { + return timeMillis; + } + + /** + * Return the total row count associated with the query. + */ + public int getRowCount() { + return rowCount; + } + + /** + * Return the origin point for the root query. + *

+ * Typically the originNode.getOriginQueryPoint().getFirstStackElement() provides the stack line that + * shows the code that invoked the query. + *

+ */ + public ObjectGraphNode getOriginNode() { + return originNode; + } +} diff --git a/src/main/java/io/ebean/config/SlowQueryListener.java b/src/main/java/io/ebean/config/SlowQueryListener.java new file mode 100644 index 000000000..19231d854 --- /dev/null +++ b/src/main/java/io/ebean/config/SlowQueryListener.java @@ -0,0 +1,13 @@ +package io.ebean.config; + +/** + * Listener for slow query events. + */ +@FunctionalInterface +public interface SlowQueryListener { + + /** + * Process a slow query event. + */ + void process(SlowQueryEvent event); +} diff --git a/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java b/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java index 7bd6d64ee..8cf77b69a 100644 --- a/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java +++ b/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java @@ -205,4 +205,9 @@ public interface SpiEbeanServer extends EbeanServer, BeanLoader, BeanCollectionL * Return the DataTimeZone to use when reading/writing timestamps via JDBC. */ DataTimeZone getDataTimeZone(); + + /** + * Check for slow query event. + */ + void slowQueryCheck(long executionTimeMicros, int rowCount, SpiQuery query); } diff --git a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java index 3292e5022..2ea0ac091 100644 --- a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java +++ b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java @@ -20,8 +20,6 @@ import io.ebean.SqlRow; import io.ebean.SqlUpdate; import io.ebean.Transaction; import io.ebean.TransactionCallback; -import io.ebean.TxCallable; -import io.ebean.TxRunnable; import io.ebean.TxScope; import io.ebean.Update; import io.ebean.UpdateQuery; @@ -43,6 +41,8 @@ import io.ebean.config.TenantMode; import io.ebean.config.dbplatform.DatabasePlatform; import io.ebean.dbmigration.DdlGenerator; import io.ebean.event.BeanPersistController; +import io.ebean.config.SlowQueryEvent; +import io.ebean.config.SlowQueryListener; import io.ebean.event.readaudit.ReadAuditLogger; import io.ebean.event.readaudit.ReadAuditPrepare; import io.ebean.meta.MetaInfoManager; @@ -205,6 +205,10 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { private final boolean collectQueryStatsByNode; + private final long slowQueryMicros; + + private final SlowQueryListener slowQueryListener; + /** * Cache used to collect statistics based on ObjectGraphNode (used to highlight lazy loading origin points). */ @@ -230,6 +234,8 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { this.encryptKeyManager = serverConfig.getEncryptKeyManager(); this.defaultPersistenceContextScope = serverConfig.getPersistenceContextScope(); this.currentTenantProvider = serverConfig.getCurrentTenantProvider(); + this.slowQueryMicros = config.getSlowQueryMicros(); + this.slowQueryListener = config.getSlowQueryListener(); this.beanDescriptorManager = config.getBeanDescriptorManager(); beanDescriptorManager.setEbeanServer(this); @@ -2221,4 +2227,12 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { } } + @Override + public void slowQueryCheck(long timeMicros, int rowCount, SpiQuery query) { + if (timeMicros > slowQueryMicros) { + if (slowQueryListener != null) { + slowQueryListener.process(new SlowQueryEvent(query.getGeneratedSql(), timeMicros / 1000L, rowCount, query.getParentNode())); + } + } + } } diff --git a/src/main/java/io/ebeaninternal/server/core/DefaultSlowQueryListener.java b/src/main/java/io/ebeaninternal/server/core/DefaultSlowQueryListener.java new file mode 100644 index 000000000..e6e02833e --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/core/DefaultSlowQueryListener.java @@ -0,0 +1,26 @@ +package io.ebeaninternal.server.core; + +import io.ebean.bean.ObjectGraphNode; +import io.ebean.config.SlowQueryEvent; +import io.ebean.config.SlowQueryListener; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +/** + * Default slow query listener implementation that logs a warning message. + */ +class DefaultSlowQueryListener implements SlowQueryListener { + + private static final Logger log = LoggerFactory.getLogger("io.ebean.SlowQuery"); + + @Override + public void process(SlowQueryEvent event) { + + String firstStack = ""; + ObjectGraphNode node = event.getOriginNode(); + if (node != null) { + firstStack = node.getOriginQueryPoint().getFirstStackElement(); + } + log.warn("Slow query warning - millis:{} rows:{} caller[{}] sql[{}]", event.getTimeMillis(), event.getRowCount(), firstStack, event.getSql()); + } +} diff --git a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java index bc8c19964..2141012d9 100644 --- a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java +++ b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java @@ -8,6 +8,7 @@ import io.ebean.config.ExternalTransactionManager; import io.ebean.config.ServerConfig; import io.ebean.config.dbplatform.DatabasePlatform; import io.ebean.config.dbplatform.DbHistorySupport; +import io.ebean.config.SlowQueryListener; import io.ebean.event.changelog.ChangeLogListener; import io.ebean.event.changelog.ChangeLogPrepare; import io.ebean.event.changelog.ChangeLogRegister; @@ -432,4 +433,30 @@ public class InternalConfiguration { public ServerCacheManager cache() { return new DefaultCacheAdapter(cacheManager); } + + /** + * Return the slow query warning limit in micros. + */ + long getSlowQueryMicros() { + long millis = serverConfig.getSlowQueryMillis(); + return (millis < 1) ? Long.MAX_VALUE : millis * 1000L; + } + + /** + * Return the SlowQueryListener with a default that logs a warning message. + */ + SlowQueryListener getSlowQueryListener() { + long millis = serverConfig.getSlowQueryMillis(); + if (millis < 1) { + return null; + } + SlowQueryListener listener = serverConfig.getSlowQueryListener(); + if (listener == null) { + listener = serverConfig.service(SlowQueryListener.class); + if (listener == null) { + listener = new DefaultSlowQueryListener(); + } + } + return listener; + } } diff --git a/src/main/java/io/ebeaninternal/server/core/OrmQueryRequest.java b/src/main/java/io/ebeaninternal/server/core/OrmQueryRequest.java index 778f2a480..71242c64b 100644 --- a/src/main/java/io/ebeaninternal/server/core/OrmQueryRequest.java +++ b/src/main/java/io/ebeaninternal/server/core/OrmQueryRequest.java @@ -597,4 +597,11 @@ public final class OrmQueryRequest extends BeanRequest implements BeanQueryRe public Object getTenantId() { return (transaction == null) ? null : transaction.getTenantId(); } + + /** + * Check for slow query event. + */ + public void slowQueryCheck(long executionTimeMicros, int rowCount) { + ebeanServer.slowQueryCheck(executionTimeMicros, rowCount, query); + } } diff --git a/src/main/java/io/ebeaninternal/server/query/CQuery.java b/src/main/java/io/ebeaninternal/server/query/CQuery.java index fdb0dd692..eca6e71ec 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQuery.java +++ b/src/main/java/io/ebeaninternal/server/query/CQuery.java @@ -36,7 +36,6 @@ import java.util.ArrayList; import java.util.Collection; import java.util.List; import java.util.Map; -import java.util.concurrent.TimeUnit; /** * An object that represents a SqlSelect statement. @@ -561,16 +560,28 @@ public class CQuery implements DbReadContext, CancelableQuery { return collection; } + /** + * Update execution stats and check for slow query. + */ void updateExecutionStatistics() { - try { - long exeNano = System.nanoTime() - startNano; - executionTimeMicros = TimeUnit.NANOSECONDS.toMicros(exeNano); + updateStatistics(); + request.slowQueryCheck(executionTimeMicros, rowCount); + } + /** + * Update execution stats but skip slow query check as expected large query. + */ + void updateExecutionStatisticsIterator() { + updateStatistics(); + } + + private void updateStatistics() { + try { + executionTimeMicros = (System.nanoTime() - startNano) / 1000L; if (autoTuneProfiling) { profilingListener.collectQueryInfo(objectGraphNode, loadedBeanCount, executionTimeMicros); } queryPlan.executionTime(loadedBeanCount, executionTimeMicros, objectGraphNode); - } catch (Exception e) { logger.error("Error updating execution statistics", e); } diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java b/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java index 91be22f35..088fba985 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java @@ -50,7 +50,7 @@ class CQueryFetchSingleAttribute { private String bindLog; - private int executionTimeMicros; + private long executionTimeMicros; private int rowCount; @@ -91,20 +91,17 @@ class CQueryFetchSingleAttribute { long startNano = System.nanoTime(); try { - prepareExecute(); List result = new ArrayList<>(); - while (dataReader.next()) { result.add(scalarType.read(dataReader)); dataReader.resetColumnPosition(); rowCount++; } - long exeNano = System.nanoTime() - startNano; - executionTimeMicros = (int) exeNano / 1000; - + executionTimeMicros = (System.nanoTime() - startNano) / 1000L; + request.slowQueryCheck(executionTimeMicros, rowCount); return result; } finally { diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryIteratorSimple.java b/src/main/java/io/ebeaninternal/server/query/CQueryIteratorSimple.java index 32f7eddff..a113cf760 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryIteratorSimple.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryIteratorSimple.java @@ -38,7 +38,7 @@ class CQueryIteratorSimple implements QueryIterator { @Override public void close() { - cquery.updateExecutionStatistics(); + cquery.updateExecutionStatisticsIterator(); cquery.close(); request.endTransIfRequired(); } diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryIteratorWithBuffer.java b/src/main/java/io/ebeaninternal/server/query/CQueryIteratorWithBuffer.java index 8ba3fd58c..da07687ac 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryIteratorWithBuffer.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryIteratorWithBuffer.java @@ -58,7 +58,7 @@ class CQueryIteratorWithBuffer implements QueryIterator { @Override public void close() { - cquery.updateExecutionStatistics(); + cquery.updateExecutionStatisticsIterator(); cquery.close(); request.endTransIfRequired(); } diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java b/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java index f2c6c3e58..c418086d1 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java @@ -47,7 +47,7 @@ class CQueryRowCount { private String bindLog; - private int executionTimeMicros; + private long executionTimeMicros; private int rowCount; @@ -99,7 +99,6 @@ class CQueryRowCount { long startNano = System.nanoTime(); try { - SpiTransaction t = request.getTransaction(); Connection conn = t.getInternalConnection(); pstmt = conn.prepareStatement(sql); @@ -110,16 +109,14 @@ class CQueryRowCount { bindLog = predicates.bind(pstmt, conn); rset = pstmt.executeQuery(); - if (!rset.next()) { throw new PersistenceException("Expecting 1 row but got none?"); } rowCount = rset.getInt(1); - long exeNano = System.nanoTime() - startNano; - executionTimeMicros = (int) exeNano / 1000; - + executionTimeMicros = (System.nanoTime() - startNano) / 1000L; + request.slowQueryCheck(executionTimeMicros, rowCount); return rowCount; } finally { diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java b/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java index e4c1a6d89..9c8faef06 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java @@ -39,7 +39,7 @@ class CQueryUpdate { private String bindLog; - private int executionTimeMicros; + private long executionTimeMicros; private int rowCount; @@ -90,7 +90,6 @@ class CQueryUpdate { long startNano = System.nanoTime(); try { - SpiTransaction t = request.getTransaction(); Connection conn = t.getInternalConnection(); pstmt = conn.prepareStatement(sql); @@ -102,9 +101,8 @@ class CQueryUpdate { bindLog = predicates.bind(pstmt, conn); rowCount = pstmt.executeUpdate(); - long exeNano = System.nanoTime() - startNano; - executionTimeMicros = (int) exeNano / 1000; - + executionTimeMicros = (System.nanoTime() - startNano) / 1000L; + request.slowQueryCheck(executionTimeMicros, rowCount); return rowCount; } finally { diff --git a/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java b/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java index 9f9180a22..9e6b16af6 100644 --- a/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java +++ b/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java @@ -799,4 +799,9 @@ public class TDSpiEbeanServer implements SpiEbeanServer { public void insertAll(Collection beans, Transaction transaction) { } + + @Override + public void slowQueryCheck(long executionTimeMicros, int rowCount, SpiQuery query) { + + } }