#1027 - ENH: Add a Slow query event listener ... to log or listen to queries that exceed some defined execution time

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.
    * <p>
@@ -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);

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.
+   * <p>
+   * Typically the <code>originNode.getOriginQueryPoint().getFirstStackElement()</code> provides the stack line that
+   * shows the code that invoked the query.
+   * </p>
+   */
+  public ObjectGraphNode getOriginNode() {
+    return originNode;
+  }
+}

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);
+}

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

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()));
+      }
+    }
+  }
 }

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());
+  }
+}

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

src/main/java/io/ebeaninternal/server/core/OrmQueryRequest.java

@@ -597,4 +597,11 @@ public final class OrmQueryRequest<T> 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);
+  }
 }

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<T> 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);
     }

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<Object> 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 {

src/main/java/io/ebeaninternal/server/query/CQueryIteratorSimple.java

@@ -38,7 +38,7 @@ class CQueryIteratorSimple<T> implements QueryIterator<T> {
 
   @Override
   public void close() {
-    cquery.updateExecutionStatistics();
+    cquery.updateExecutionStatisticsIterator();
     cquery.close();
     request.endTransIfRequired();
   }

src/main/java/io/ebeaninternal/server/query/CQueryIteratorWithBuffer.java

@@ -58,7 +58,7 @@ class CQueryIteratorWithBuffer<T> implements QueryIterator<T> {
 
   @Override
   public void close() {
-    cquery.updateExecutionStatistics();
+    cquery.updateExecutionStatisticsIterator();
     cquery.close();
     request.endTransIfRequired();
   }

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 {

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 {