From ee8bb5ef751ccbc9cd9b1d6fdd0b561ec8e781a7 Mon Sep 17 00:00:00 2001 From: Robin Bygrave Date: Tue, 30 Mar 2021 23:19:21 +1300 Subject: [PATCH] #2211 - Improve query plan capture - Add default mechanism to log captured query plans --- .../java/io/ebean/config/DatabaseConfig.java | 94 ++++++++++++++++++- .../io/ebean/config/QueryPlanCapture.java | 34 +++++++ .../io/ebean/config/QueryPlanListener.java | 13 +++ .../server/core/DefaultQueryPlanListener.java | 25 +++++ .../server/core/DefaultServer.java | 33 +++++-- .../io/ebean/config/ServerConfigTest.java | 15 +++ 6 files changed, 206 insertions(+), 8 deletions(-) create mode 100644 ebean-api/src/main/java/io/ebean/config/QueryPlanCapture.java create mode 100644 ebean-api/src/main/java/io/ebean/config/QueryPlanListener.java create mode 100644 ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java diff --git a/ebean-api/src/main/java/io/ebean/config/DatabaseConfig.java b/ebean-api/src/main/java/io/ebean/config/DatabaseConfig.java index 49c458743..1cbfa9d3e 100644 --- a/ebean-api/src/main/java/io/ebean/config/DatabaseConfig.java +++ b/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. + *

+ * 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. + *

+ * 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. */ diff --git a/ebean-api/src/main/java/io/ebean/config/QueryPlanCapture.java b/ebean-api/src/main/java/io/ebean/config/QueryPlanCapture.java new file mode 100644 index 000000000..6f34097fe --- /dev/null +++ b/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 plans; + + public QueryPlanCapture(Database database, List 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 getPlans() { + return plans; + } +} diff --git a/ebean-api/src/main/java/io/ebean/config/QueryPlanListener.java b/ebean-api/src/main/java/io/ebean/config/QueryPlanListener.java new file mode 100644 index 000000000..8368186cf --- /dev/null +++ b/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); +} diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java new file mode 100644 index 000000000..051d331ba --- /dev/null +++ b/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()); + } + } +} diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultServer.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultServer.java index 0e4d22768..52b94bfb6 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultServer.java +++ b/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 plans = metaInfoManager.queryPlanCollectNow(request); + QueryPlanListener listener = config.getQueryPlanListener(); + if (listener == null) { + listener = DefaultQueryPlanListener.INSTANT; + } + listener.process(new QueryPlanCapture(this, plans)); } @Override diff --git a/ebean-core/src/test/java/io/ebean/config/ServerConfigTest.java b/ebean-core/src/test/java/io/ebean/config/ServerConfigTest.java index 8fda93985..b23ccdbb6 100644 --- a/ebean-core/src/test/java/io/ebean/config/ServerConfigTest.java +++ b/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()); }