#2211 - Improve query plan capture - Add default mechanism to log captured query plans

ebean-api/src/main/java/io/ebean/config/DatabaseConfig.java

@@ -498,7 +498,7 @@ public class DatabaseConfig {
   private boolean notifyL2CacheInForeground;
 
   /**
-   * Set to true to support query plan capture.
+   * Set to true to enable bind capture required for query plan capture.
    */
   private boolean collectQueryPlans;
 
@@ -507,6 +507,15 @@ public class DatabaseConfig {
    */
   private long collectQueryPlanThresholdMicros = Long.MAX_VALUE;
 
+  /**
+   * Set to true to enable automatic query plan capture.
+   */
+  private boolean queryPlanCapture;
+  private long queryPlanCapturePeriodSecs = 60 * 10; // 10 minutes
+  private long queryPlanCaptureMaxTimeMillis = 10_000; // 10 seconds
+  private int queryPlanCaptureMaxCount = 10;
+  private QueryPlanListener queryPlanListener;
+
   /**
    * The time in millis used to determine when a query is alerted for being slow.
    */
@@ -1045,7 +1054,6 @@ public class DatabaseConfig {
    * This is a performance optimisation to reduce the number times Ebean
    * requests a sequence to be used as an Id for a bean (aka reduce network
    * chatter).
-
    */
   public void setDatabaseSequenceBatchSize(int databaseSequenceBatchSize) {
     platformConfig.setDatabaseSequenceBatchSize(databaseSequenceBatchSize);
@@ -2807,6 +2815,10 @@ public class DatabaseConfig {
     slowQueryMillis = p.getLong("slowQueryMillis", slowQueryMillis);
     collectQueryPlans = p.getBoolean("collectQueryPlans", collectQueryPlans);
     collectQueryPlanThresholdMicros = p.getLong("collectQueryPlanThresholdMicros", collectQueryPlanThresholdMicros);
+    queryPlanCapture = p.getBoolean("queryPlan.capture", queryPlanCapture);
+    queryPlanCapturePeriodSecs = p.getLong("queryPlan.capturePeriodSecs", queryPlanCapturePeriodSecs);
+    queryPlanCaptureMaxTimeMillis = p.getLong("queryPlan.captureMaxTimeMillis", queryPlanCaptureMaxTimeMillis);
+    queryPlanCaptureMaxCount = p.getInt("queryPlan.captureMaxCount", queryPlanCaptureMaxCount);
     docStoreOnly = p.getBoolean("docStoreOnly", docStoreOnly);
     disableL2Cache = p.getBoolean("disableL2Cache", disableL2Cache);
     localOnlyL2Cache = p.getBoolean("localOnlyL2Cache", localOnlyL2Cache);
@@ -3201,6 +3213,84 @@ public class DatabaseConfig {
     this.collectQueryPlanThresholdMicros = collectQueryPlanThresholdMicros;
   }
 
+  /**
+   * Return true if periodic capture of query plans is enabled.
+   */
+  public boolean isQueryPlanCapture() {
+    return queryPlanCapture;
+  }
+
+  /**
+   * Set to true to turn on periodic capture of query plans.
+   */
+  public void setQueryPlanCapture(boolean queryPlanCapture) {
+    this.queryPlanCapture = queryPlanCapture;
+  }
+
+  /**
+   * Return the frequency to capture query plans.
+   */
+  public long getQueryPlanCapturePeriodSecs() {
+    return queryPlanCapturePeriodSecs;
+  }
+
+  /**
+   * Set the frequency in seconds to capture query plans.
+   */
+  public void setQueryPlanCapturePeriodSecs(long queryPlanCapturePeriodSecs) {
+    this.queryPlanCapturePeriodSecs = queryPlanCapturePeriodSecs;
+  }
+
+  /**
+   * Return the time after which a capture query plans request will
+   * stop capturing more query plans.
+   * <p>
+   * Effectively this controls the amount of load/time we want to
+   * allow for query plan capture.
+   */
+  public long getQueryPlanCaptureMaxTimeMillis() {
+    return queryPlanCaptureMaxTimeMillis;
+  }
+
+  /**
+   * Set the time after which a capture query plans request will
+   * stop capturing more query plans.
+   * <p>
+   * Effectively this controls the amount of load/time we want to
+   * allow for query plan capture.
+   */
+  public void setQueryPlanCaptureMaxTimeMillis(long queryPlanCaptureMaxTimeMillis) {
+    this.queryPlanCaptureMaxTimeMillis = queryPlanCaptureMaxTimeMillis;
+  }
+
+  /**
+   * Return the max number of query plans captured per request.
+   */
+  public int getQueryPlanCaptureMaxCount() {
+    return queryPlanCaptureMaxCount;
+  }
+
+  /**
+   * Set the max number of query plans captured per request.
+   */
+  public void setQueryPlanCaptureMaxCount(int queryPlanCaptureMaxCount) {
+    this.queryPlanCaptureMaxCount = queryPlanCaptureMaxCount;
+  }
+
+  /**
+   * Return the listener used to process captured query plans.
+   */
+  public QueryPlanListener getQueryPlanListener() {
+    return queryPlanListener;
+  }
+
+  /**
+   * Set the listener used to process captured query plans.
+   */
+  public void setQueryPlanListener(QueryPlanListener queryPlanListener) {
+    this.queryPlanListener = queryPlanListener;
+  }
+
   /**
    * Return true if metrics should be dumped when the server is shutdown.
    */

ebean-api/src/main/java/io/ebean/config/QueryPlanCapture.java

@@ -0,0 +1,34 @@
+package io.ebean.config;
+
+import io.ebean.Database;
+import io.ebean.meta.MetaQueryPlan;
+
+import java.util.List;
+
+/**
+ * The captured query plans.
+ */
+public class QueryPlanCapture {
+
+  private final Database database;
+  private final List<MetaQueryPlan> plans;
+
+  public QueryPlanCapture(Database database, List<MetaQueryPlan> plans) {
+    this.database = database;
+    this.plans = plans;
+  }
+
+  /**
+   * Return the database the plans were captured for.
+   */
+  public Database getDatabase() {
+    return database;
+  }
+
+  /**
+   * Return the captured query plans.
+   */
+  public List<MetaQueryPlan> getPlans() {
+    return plans;
+  }
+}

ebean-api/src/main/java/io/ebean/config/QueryPlanListener.java

@@ -0,0 +1,13 @@
+package io.ebean.config;
+
+/**
+ * EXPERIMENTAL: Listener for captured query plans.
+ */
+@FunctionalInterface
+public interface QueryPlanListener {
+
+  /**
+   * Process the captured query plans.
+   */
+  void process(QueryPlanCapture capture);
+}

ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java

@@ -0,0 +1,25 @@
+package io.ebeaninternal.server.core;
+
+import io.ebean.config.QueryPlanCapture;
+import io.ebean.config.QueryPlanListener;
+import io.ebean.meta.MetaQueryPlan;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+class DefaultQueryPlanListener implements QueryPlanListener {
+
+  static final QueryPlanListener INSTANT = new DefaultQueryPlanListener();
+
+  private static final Logger log = LoggerFactory.getLogger("io.ebean.QUERYPLAN");
+
+  @Override
+  public void process(QueryPlanCapture capture) {
+    // better to log this in JSON form?
+    String dbName = capture.getDatabase().getName();
+    for (MetaQueryPlan plan : capture.getPlans()) {
+      log.info("queryPlan  db:{} label:{} queryTimeMicros:{} loc:{} sql:{} bind:{} plan:{}",
+        dbName, plan.getLabel(), plan.getQueryTimeMicros(), plan.getProfileLocation(),
+        plan.getSql(), plan.getBind(), plan.getPlan());
+    }
+  }
+}

ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultServer.java

@@ -45,12 +45,7 @@ import io.ebean.bean.PersistenceContext.WithOption;
 import io.ebean.bean.SingleBeanLoader;
 import io.ebean.cache.ServerCacheManager;
 import io.ebean.common.CopyOnFirstWriteList;
-import io.ebean.config.CurrentTenantProvider;
-import io.ebean.config.DatabaseConfig;
-import io.ebean.config.EncryptKeyManager;
-import io.ebean.config.SlowQueryEvent;
-import io.ebean.config.SlowQueryListener;
-import io.ebean.config.TenantMode;
+import io.ebean.config.*;
 import io.ebean.config.dbplatform.DatabasePlatform;
 import io.ebean.event.BeanPersistController;
 import io.ebean.event.ShutdownManager;
@@ -145,6 +140,7 @@ import java.util.Optional;
 import java.util.Set;
 import java.util.Spliterator;
 import java.util.concurrent.Callable;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.locks.ReentrantLock;
 import java.util.function.Consumer;
 import java.util.function.Function;
@@ -404,6 +400,31 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer {
       migrationRunner.loadProperties(config.getProperties());
       migrationRunner.run(config.getDataSource());
     }
+    startQueryPlanCapture();
+  }
+
+  private void startQueryPlanCapture() {
+    if (config.isQueryPlanCapture()) {
+      long secs = config.getQueryPlanCapturePeriodSecs();
+      if (secs > 10) {
+        logger.info("capture query plan enabled, every {}secs", secs);
+        backgroundExecutor.scheduleWithFixedDelay(this::collectQueryPlans, secs, secs, TimeUnit.SECONDS);
+      }
+    }
+  }
+
+  private void collectQueryPlans() {
+    QueryPlanRequest request = new QueryPlanRequest();
+    request.setMaxCount(config.getQueryPlanCaptureMaxCount());
+    request.setMaxTimeMillis(config.getQueryPlanCaptureMaxTimeMillis());
+
+    // obtains query explain plans ...
+    List<MetaQueryPlan> plans = metaInfoManager.queryPlanCollectNow(request);
+    QueryPlanListener listener = config.getQueryPlanListener();
+    if (listener == null) {
+      listener = DefaultQueryPlanListener.INSTANT;
+    }
+    listener.process(new QueryPlanCapture(this, plans));
   }
 
   @Override

ebean-core/src/test/java/io/ebean/config/ServerConfigTest.java

@@ -76,6 +76,11 @@ public class ServerConfigTest {
     props.setProperty("forUpdateNoKey", "true");
     props.setProperty("defaultServer", "false");
 
+    props.setProperty("queryPlan.capture", "true");
+    props.setProperty("queryPlan.capturePeriodSecs", "42");
+    props.setProperty("queryPlan.captureMaxTimeMillis", "560");
+    props.setProperty("queryPlan.captureMaxCount", "7");
+
     serverConfig.loadFromProperties(props);
 
     assertFalse(serverConfig.isDefaultServer());
@@ -106,6 +111,11 @@ public class ServerConfigTest {
     assertEquals(4, serverConfig.getBackgroundExecutorSchedulePoolSize());
     assertEquals(98, serverConfig.getBackgroundExecutorShutdownSecs());
 
+    assertTrue(serverConfig.isQueryPlanCapture());
+    assertEquals(42, serverConfig.getQueryPlanCapturePeriodSecs());
+    assertEquals(560, serverConfig.getQueryPlanCaptureMaxTimeMillis());
+    assertEquals(7, serverConfig.getQueryPlanCaptureMaxCount());
+
     assertThat(serverConfig.getMappingLocations()).containsExactly("classpath:/foo","bar");
 
     serverConfig.setPersistBatch(PersistBatch.NONE);
@@ -146,6 +156,11 @@ public class ServerConfigTest {
     assertTrue(serverConfig.isAutoLoadModuleInfo());
     assertEquals(Long.MAX_VALUE, serverConfig.getCollectQueryPlanThresholdMicros());
 
+    assertFalse(serverConfig.isQueryPlanCapture());
+    assertEquals(600, serverConfig.getQueryPlanCapturePeriodSecs());
+    assertEquals(10000L, serverConfig.getQueryPlanCaptureMaxTimeMillis());
+    assertEquals(10, serverConfig.getQueryPlanCaptureMaxCount());
+
     serverConfig.setLoadModuleInfo(false);
     assertFalse(serverConfig.isAutoLoadModuleInfo());
   }