diff --git a/src/main/java/io/ebean/config/ServerConfig.java b/src/main/java/io/ebean/config/ServerConfig.java index 53127965d..3e346570a 100644 --- a/src/main/java/io/ebean/config/ServerConfig.java +++ b/src/main/java/io/ebean/config/ServerConfig.java @@ -497,6 +497,11 @@ public class ServerConfig { */ private boolean collectQueryPlans; + /** + * The default threshold in micros for collecting query plans. + */ + private long collectQueryPlanThresholdMicros = Long.MAX_VALUE; + /** * The time in millis used to determine when a query is alerted for being slow. */ @@ -2857,6 +2862,7 @@ public class ServerConfig { queryPlanTTLSeconds = p.getInt("queryPlanTTLSeconds", queryPlanTTLSeconds); slowQueryMillis = p.getLong("slowQueryMillis", slowQueryMillis); collectQueryPlans = p.getBoolean("collectQueryPlans", collectQueryPlans); + collectQueryPlanThresholdMicros = p.getLong("collectQueryPlanThresholdMicros", collectQueryPlanThresholdMicros); docStoreOnly = p.getBoolean("docStoreOnly", docStoreOnly); disableL2Cache = p.getBoolean("disableL2Cache", disableL2Cache); enabledL2Regions = p.get("enabledL2Regions", enabledL2Regions); @@ -3242,6 +3248,20 @@ public class ServerConfig { this.collectQueryPlans = collectQueryPlans; } + /** + * Return the query plan collection threshold in microseconds. + */ + public long getCollectQueryPlanThresholdMicros() { + return collectQueryPlanThresholdMicros; + } + + /** + * Set the query plan collection threshold in microseconds. + */ + public void setCollectQueryPlanThresholdMicros(long collectQueryPlanThresholdMicros) { + this.collectQueryPlanThresholdMicros = collectQueryPlanThresholdMicros; + } + /** * Return true if metrics should be dumped when the server is shutdown. */ diff --git a/src/main/java/io/ebeaninternal/api/ExtraMetrics.java b/src/main/java/io/ebeaninternal/api/ExtraMetrics.java new file mode 100644 index 000000000..dac31b2a9 --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/ExtraMetrics.java @@ -0,0 +1,46 @@ +package io.ebeaninternal.api; + +import io.ebean.meta.MetricType; +import io.ebean.meta.MetricVisitor; +import io.ebean.metric.MetricFactory; +import io.ebean.metric.TimedMetric; + +/** + * Extra metrics collected to measure internal behaviour. + */ +public class ExtraMetrics { + + private final TimedMetric bindCapture; + private final TimedMetric planCollect; + + /** + * Create the extra metrics. + */ + public ExtraMetrics() { + final MetricFactory factory = MetricFactory.get(); + this.bindCapture = factory.createTimedMetric(MetricType.ORM, "ebean.queryplan.bindcapture"); + this.planCollect = factory.createTimedMetric(MetricType.ORM, "ebean.queryplan.collect"); + } + + /** + * Timed metric for bind capture used with query plan collection. + */ + public TimedMetric getBindCapture() { + return bindCapture; + } + + /** + * Timed metric for query plan collection. + */ + public TimedMetric getPlanCollect() { + return planCollect; + } + + /** + * Collect the metrics. + */ + public void visitMetrics(MetricVisitor visitor) { + bindCapture.visit(visitor); + planCollect.visit(visitor); + } +} diff --git a/src/main/java/io/ebeaninternal/api/NoopQueryBindCapture.java b/src/main/java/io/ebeaninternal/api/NoopQueryBindCapture.java new file mode 100644 index 000000000..e4c747497 --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/NoopQueryBindCapture.java @@ -0,0 +1,22 @@ +package io.ebeaninternal.api; + +import io.ebean.meta.QueryPlanRequest; +import io.ebeaninternal.server.type.bindcapture.BindCapture; + +class NoopQueryBindCapture implements SpiQueryBindCapture { + + @Override + public boolean collectFor(long timeMicros) { + return false; + } + + @Override + public void setBind(BindCapture bindCapture, long timeMicros, long startNanos) { + // do nothing + } + + @Override + public void collectQueryPlan(QueryPlanRequest request) { + // do nothing + } +} diff --git a/src/main/java/io/ebeaninternal/api/NoopQueryPlanManager.java b/src/main/java/io/ebeaninternal/api/NoopQueryPlanManager.java new file mode 100644 index 000000000..7b97d821f --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/NoopQueryPlanManager.java @@ -0,0 +1,9 @@ +package io.ebeaninternal.api; + +class NoopQueryPlanManager implements QueryPlanManager { + + @Override + public SpiQueryBindCapture createBindCapture(SpiQueryPlan queryPlan) { + return SpiQueryBindCapture.NOOP; + } +} diff --git a/src/main/java/io/ebeaninternal/api/QueryPlanManager.java b/src/main/java/io/ebeaninternal/api/QueryPlanManager.java new file mode 100644 index 000000000..fea4d1976 --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/QueryPlanManager.java @@ -0,0 +1,14 @@ +package io.ebeaninternal.api; + +/** + * Manage query plan capture. + */ +public interface QueryPlanManager { + + QueryPlanManager NOOP = new NoopQueryPlanManager(); + + /** + * Create the bind capture for the given query plan. + */ + SpiQueryBindCapture createBindCapture(SpiQueryPlan queryPlan); +} diff --git a/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java b/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java index 0afa7726e..36b1f3901 100644 --- a/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java +++ b/src/main/java/io/ebeaninternal/api/SpiEbeanServer.java @@ -12,7 +12,6 @@ import io.ebean.TxScope; import io.ebean.bean.BeanCollectionLoader; import io.ebean.bean.BeanLoader; import io.ebean.bean.CallOrigin; -import io.ebean.bean.ObjectGraphNode; import io.ebean.config.ServerConfig; import io.ebean.config.dbplatform.DatabasePlatform; import io.ebean.event.readaudit.ReadAuditLogger; @@ -311,4 +310,9 @@ public interface SpiEbeanServer extends ExtendedServer, EbeanServer, BeanLoader, * Execute the sql update regardless of transaction batch mode. */ int executeNow(SpiSqlUpdate sqlUpdate); + + /** + * Create a query bind capture for the given query plan. + */ + SpiQueryBindCapture createQueryBindCapture(SpiQueryPlan queryPlan); } diff --git a/src/main/java/io/ebeaninternal/api/SpiQueryBindCapture.java b/src/main/java/io/ebeaninternal/api/SpiQueryBindCapture.java new file mode 100644 index 000000000..9088f54ad --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/SpiQueryBindCapture.java @@ -0,0 +1,31 @@ +package io.ebeaninternal.api; + +import io.ebean.meta.QueryPlanRequest; +import io.ebeaninternal.server.type.bindcapture.BindCapture; + +/** + * Capture query bind values and with those actual database query plans. + */ +public interface SpiQueryBindCapture { + + /** + * NOOP implementation. + */ + SpiQueryBindCapture NOOP = new NoopQueryBindCapture(); + + /** + * Return true if the query just executed should be bind captured to collect + * the query plan from (as the query time is large / interesting). + */ + boolean collectFor(long timeMicros); + + /** + * Set the bind capture and the related query execution time. + */ + void setBind(BindCapture bindCapture, long timeMicros, long startNanos); + + /** + * Collect the query execution plan usually executing the query to do so. + */ + void collectQueryPlan(QueryPlanRequest request); +} diff --git a/src/main/java/io/ebeaninternal/api/SpiQueryPlan.java b/src/main/java/io/ebeaninternal/api/SpiQueryPlan.java new file mode 100644 index 000000000..e06243df8 --- /dev/null +++ b/src/main/java/io/ebeaninternal/api/SpiQueryPlan.java @@ -0,0 +1,34 @@ +package io.ebeaninternal.api; + +import io.ebean.ProfileLocation; + +/** + * The internal ORM "query plan". + */ +public interface SpiQueryPlan { + + /** + * The related entity bean type + */ + Class getBeanType(); + + /** + * The plan name. + */ + String getName(); + + /** + * The hash for the query plan. + */ + String getHash(); + + /** + * The SQL for the query plan. + */ + String getSql(); + + /** + * The related profile location. + */ + ProfileLocation getProfileLocation(); +} diff --git a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java index c504d4061..aa59462c1 100644 --- a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java +++ b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java @@ -38,7 +38,6 @@ import io.ebean.bean.BeanCollection; import io.ebean.bean.CallOrigin; import io.ebean.bean.EntityBean; import io.ebean.bean.EntityBeanIntercept; -import io.ebean.bean.ObjectGraphNode; import io.ebean.bean.PersistenceContext; import io.ebean.bean.PersistenceContext.WithOption; import io.ebean.cache.ServerCacheManager; @@ -64,8 +63,10 @@ import io.ebean.plugin.SpiServer; import io.ebean.text.csv.CsvReader; import io.ebean.text.json.JsonContext; import io.ebean.util.JdbcClose; +import io.ebeaninternal.api.ExtraMetrics; import io.ebeaninternal.api.LoadBeanRequest; import io.ebeaninternal.api.LoadManyRequest; +import io.ebeaninternal.api.QueryPlanManager; import io.ebeaninternal.api.ScopedTransaction; import io.ebeaninternal.api.SpiBackgroundExecutor; import io.ebeaninternal.api.SpiDtoQuery; @@ -74,6 +75,8 @@ import io.ebeaninternal.api.SpiJsonContext; import io.ebeaninternal.api.SpiLogManager; import io.ebeaninternal.api.SpiQuery; import io.ebeaninternal.api.SpiQuery.Type; +import io.ebeaninternal.api.SpiQueryBindCapture; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.api.SpiSqlQuery; import io.ebeaninternal.api.SpiSqlUpdate; import io.ebeaninternal.api.SpiTransaction; @@ -138,7 +141,6 @@ import java.util.Optional; import java.util.Set; import java.util.Spliterator; import java.util.concurrent.Callable; -import java.util.concurrent.ConcurrentHashMap; import java.util.function.Consumer; import java.util.function.Function; import java.util.function.Predicate; @@ -162,6 +164,10 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { private final TransactionManager transactionManager; + private final QueryPlanManager queryPlanManager; + + private final ExtraMetrics extraMetrics; + private final DataTimeZone dataTimeZone; /** @@ -256,6 +262,8 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { this.serverCacheManager = cache; this.databasePlatform = config.getDatabasePlatform(); this.backgroundExecutor = config.getBackgroundExecutor(); + this.queryPlanManager = config.getQueryPlanManager(); + this.extraMetrics = config.getExtraMetrics(); this.serverName = serverConfig.getName(); this.lazyLoadBatchSize = serverConfig.getLazyLoadBatchSize(); @@ -2385,7 +2393,6 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { return Collections.emptySet(); } - /** * Returns a set of properties if saving the bean will violate the unique constraints (defined by given properties). */ @@ -2430,6 +2437,7 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { relationalQueryEngine.visitMetrics(visitor); persister.visitMetrics(visitor); } + extraMetrics.visitMetrics(visitor); visitor.visitEnd(); } @@ -2447,4 +2455,9 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { } return request.getPlans(); } + + @Override + public SpiQueryBindCapture createQueryBindCapture(SpiQueryPlan plan) { + return queryPlanManager.createBindCapture(plan); + } } diff --git a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java index f7623916b..5ebcf4d74 100644 --- a/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java +++ b/src/main/java/io/ebeaninternal/server/core/InternalConfiguration.java @@ -23,6 +23,8 @@ import io.ebean.event.readaudit.ReadAuditLogger; import io.ebean.event.readaudit.ReadAuditPrepare; import io.ebean.plugin.Plugin; import io.ebean.plugin.SpiServer; +import io.ebeaninternal.api.ExtraMetrics; +import io.ebeaninternal.api.QueryPlanManager; import io.ebeaninternal.api.SpiBackgroundExecutor; import io.ebeaninternal.api.SpiEbeanServer; import io.ebeaninternal.api.SpiJsonContext; @@ -64,9 +66,15 @@ import io.ebeaninternal.server.persist.DefaultPersister; import io.ebeaninternal.server.persist.platform.MultiValueBind; import io.ebeaninternal.server.persist.platform.PostgresMultiValueBind; import io.ebeaninternal.server.query.CQueryEngine; +import io.ebeaninternal.server.query.CQueryPlanManager; import io.ebeaninternal.server.query.DefaultOrmQueryEngine; import io.ebeaninternal.server.query.DefaultRelationalQueryEngine; import io.ebeaninternal.server.query.DtoQueryEngine; +import io.ebeaninternal.server.query.QueryPlanLogger; +import io.ebeaninternal.server.query.QueryPlanLoggerExplain; +import io.ebeaninternal.server.query.QueryPlanLoggerOracle; +import io.ebeaninternal.server.query.QueryPlanLoggerPostgres; +import io.ebeaninternal.server.query.QueryPlanLoggerSqlServer; import io.ebeaninternal.server.readaudit.DefaultReadAuditLogger; import io.ebeaninternal.server.readaudit.DefaultReadAuditPrepare; import io.ebeaninternal.server.text.json.DJsonContext; @@ -164,8 +172,10 @@ public class InternalConfiguration { private final SpiLogManager logManager; + private final ExtraMetrics extraMetrics = new ExtraMetrics(); + InternalConfiguration(boolean online, ClusterManager clusterManager, SpiBackgroundExecutor backgroundExecutor, - ServerConfig serverConfig, BootupClasses bootupClasses) { + ServerConfig serverConfig, BootupClasses bootupClasses) { this.online = online; this.serverConfig = serverConfig; @@ -242,6 +252,10 @@ public class InternalConfiguration { return clockService; } + public ExtraMetrics getExtraMetrics() { + return extraMetrics; + } + /** * Check if this is a SpiServerPlugin and if so 'collect' it to give the complete list * later on the DefaultServer for late call to configure(). @@ -433,8 +447,8 @@ public class InternalConfiguration { TransactionManagerOptions options = new TransactionManagerOptions(notifyL2CacheInForeground, serverConfig, scopeManager, clusterManager, backgroundExecutor, - indexUpdateProcessor, beanDescriptorManager, dataSource(), profileHandler(), logManager, - tableModState, cacheNotify, clockService); + indexUpdateProcessor, beanDescriptorManager, dataSource(), profileHandler(), logManager, + tableModState, cacheNotify, clockService); if (serverConfig.isExplicitTransactionBeginMode()) { return new ExplicitTransactionManager(options); @@ -527,7 +541,7 @@ public class InternalConfiguration { } private boolean isMySql(Platform platform) { - return platform.base() == Platform.MYSQL; + return platform.base() == Platform.MYSQL; } public DataTimeZone getDataTimeZone() { @@ -636,4 +650,28 @@ public class InternalConfiguration { return new DefaultServerCacheManager(builder); } + + public QueryPlanManager getQueryPlanManager() { + if (!serverConfig.isCollectQueryPlans()) { + return QueryPlanManager.NOOP; + } + long threshold = serverConfig.getCollectQueryPlanThresholdMicros(); + return new CQueryPlanManager(threshold, queryPlanLogger(databasePlatform.getPlatform())); + } + + /** + * Returns the logger to log query plans for the given platform. + */ + QueryPlanLogger queryPlanLogger(Platform platform) { + switch (platform.base()) { + case POSTGRES: + return new QueryPlanLoggerPostgres(extraMetrics); + case SQLSERVER: + return new QueryPlanLoggerSqlServer(extraMetrics); + case ORACLE: + return new QueryPlanLoggerOracle(extraMetrics); + default: + return new QueryPlanLoggerExplain(extraMetrics); + } + } } diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java index 32b8294e6..af8647a3d 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java @@ -1714,19 +1714,14 @@ public class BeanDescriptor implements BeanType, STreeType { /** * Trim query plans not used since the passed in epoch time. */ - List trimQueryPlans(long unusedSince) { - - List list = new ArrayList<>(); - + void trimQueryPlans(long unusedSince) { Iterator it = queryPlanCache.values().iterator(); while (it.hasNext()) { CQueryPlan queryPlan = it.next(); if (queryPlan.getLastQueryTime() < unusedSince) { it.remove(); - list.add(queryPlan); } } - return list; } /** diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java index 9ec66ea38..4370dd651 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptorManager.java @@ -244,17 +244,14 @@ public class BeanDescriptorManager implements BeanDescriptorMap { * Run periodic trim of query plans. */ public void scheduleBackgroundTrim() { - backgroundExecutor.executePeriodically(this::trimQueryPlans, 30L, TimeUnit.SECONDS); + backgroundExecutor.executePeriodically(this::trimQueryPlans, 60L, TimeUnit.SECONDS); } private void trimQueryPlans() { long lastUsed = System.currentTimeMillis() - (queryPlanTTLSeconds * 1000L); for (BeanDescriptor descriptor : immutableDescriptorList) { if (!descriptor.isEmbedded()) { - List trimmedPlans = descriptor.trimQueryPlans(lastUsed); - if (!trimmedPlans.isEmpty()) { - logger.trace("trimmed {} query plans for type:{}", trimmedPlans.size(), descriptor.getName()); - } + descriptor.trimQueryPlans(lastUsed); } } } diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java b/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java index 4ba444012..a2d934b29 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java @@ -1,13 +1,15 @@ package io.ebeaninternal.server.query; import io.ebean.meta.QueryPlanRequest; +import io.ebeaninternal.api.SpiQueryBindCapture; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.server.type.bindcapture.BindCapture; -class CQueryBindCapture { +class CQueryBindCapture implements SpiQueryBindCapture { private static final double multiplier = 1.3d; - private final CQueryPlan cQueryPlan; + private final SpiQueryPlan queryPlan; private final QueryPlanLogger planLogger; private BindCapture bindCapture; @@ -17,16 +19,18 @@ class CQueryBindCapture { private long lastBindCapture; - CQueryBindCapture(CQueryPlan cQueryPlan, QueryPlanLogger planLogger) { - this.cQueryPlan = cQueryPlan; + CQueryBindCapture(SpiQueryPlan queryPlan, QueryPlanLogger planLogger, long thresholdMicros) { + this.queryPlan = queryPlan; this.planLogger = planLogger; + this.thresholdMicros = thresholdMicros; } /** * Return true if we should capture the bind values for this query. */ - boolean collectFor(long timeMicros) { - return (bindCapture == null || timeMicros > thresholdMicros); + @Override + public boolean collectFor(long timeMicros) { + return timeMicros > thresholdMicros && captureCount < 10; } /** @@ -34,23 +38,25 @@ class CQueryBindCapture { * * @param bindCapture The bind values of the query * @param queryTimeMicros The query execution time + * @param startNanos The nanos start of this bind capture */ - void setBind(BindCapture bindCapture, long queryTimeMicros) { + @Override + public void setBind(BindCapture bindCapture, long queryTimeMicros, long startNanos) { synchronized (this) { + this.thresholdMicros = Math.round(queryTimeMicros * multiplier); + this.captureCount++; this.bindCapture = bindCapture; this.queryTimeMicros = queryTimeMicros; - this.thresholdMicros = Math.round(queryTimeMicros * multiplier); - captureCount++; lastBindCapture = System.currentTimeMillis(); + planLogger.addBindTimeSince(startNanos); } } - /** * Collect the query plan using already captured bind values. */ - void collectQueryPlan(QueryPlanRequest request) { - + @Override + public void collectQueryPlan(QueryPlanRequest request) { if (bindCapture == null || request.getSince() > lastBindCapture) { // no bind capture since the last capture return; @@ -58,9 +64,9 @@ class CQueryBindCapture { final BindCapture last = this.bindCapture; - DQueryPlanOutput queryPlan = planLogger.logQueryPlan(request.getConnection(), cQueryPlan, last); + DQueryPlanOutput queryPlan = planLogger.collectQueryPlan(request.getConnection(), this.queryPlan, last); if (queryPlan != null) { - queryPlan.with(queryTimeMicros, captureCount, cQueryPlan.getHash()); + queryPlan.with(queryTimeMicros, captureCount, this.queryPlan.getHash()); request.process(queryPlan); } } diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryPlan.java b/src/main/java/io/ebeaninternal/server/query/CQueryPlan.java index e8b706ada..6eceac806 100644 --- a/src/main/java/io/ebeaninternal/server/query/CQueryPlan.java +++ b/src/main/java/io/ebeaninternal/server/query/CQueryPlan.java @@ -1,7 +1,6 @@ package io.ebeaninternal.server.query; import io.ebean.ProfileLocation; -import io.ebean.config.ServerConfig; import io.ebean.config.dbplatform.SqlLimitResponse; import io.ebean.meta.MetricType; import io.ebean.meta.QueryPlanRequest; @@ -10,6 +9,8 @@ import io.ebean.metric.TimedMetric; import io.ebeaninternal.api.CQueryPlanKey; import io.ebeaninternal.api.SpiEbeanServer; import io.ebeaninternal.api.SpiQuery; +import io.ebeaninternal.api.SpiQueryBindCapture; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.server.core.OrmQueryRequest; import io.ebeaninternal.server.core.timezone.DataTimeZone; import io.ebeaninternal.server.query.CQueryPlanStats.Snapshot; @@ -47,7 +48,7 @@ import java.util.Set; * for performance tuning. *

*/ -public class CQueryPlan { +public class CQueryPlan implements SpiQueryPlan { private static final Logger logger = LoggerFactory.getLogger(CQueryPlan.class); @@ -98,13 +99,12 @@ public class CQueryPlan { private final Set dependentTables; - private final CQueryBindCapture bindCapture; + private final SpiQueryBindCapture bindCapture; /** * Create a query plan based on a OrmQueryRequest. */ CQueryPlan(OrmQueryRequest request, SqlLimitResponse sqlRes, SqlTree sqlTree, boolean rawSql, String logWhereSql) { - this.server = request.getServer(); this.dataTimeZone = server.getDataTimeZone(); this.beanType = request.getBeanDescriptor().getBeanType(); @@ -124,7 +124,7 @@ public class CQueryPlan { this.encryptedProps = sqlTree.getEncryptedProps(); this.stats = new CQueryPlanStats(this); this.dependentTables = sqlTree.dependentTables(); - this.bindCapture = initBindCapture(server.getServerConfig(), query); + this.bindCapture = initBindCapture(query); this.hash = md5Hash(); } @@ -132,7 +132,6 @@ public class CQueryPlan { * Create a query plan for a raw sql query. */ CQueryPlan(OrmQueryRequest request, String sql, SqlTree sqlTree, boolean rowNumberIncluded, String logWhereSql) { - this.server = request.getServer(); this.dataTimeZone = server.getDataTimeZone(); this.beanType = request.getBeanDescriptor().getBeanType(); @@ -152,7 +151,7 @@ public class CQueryPlan { this.encryptedProps = sqlTree.getEncryptedProps(); this.stats = new CQueryPlanStats(this); this.dependentTables = sqlTree.dependentTables(); - this.bindCapture = initBindCapture(server.getServerConfig(), query); + this.bindCapture = initBindCapture(query); this.hash = md5Hash(); } @@ -166,12 +165,8 @@ public class CQueryPlan { return "orm." + beanType.getSimpleName() + "_" + label; } - private CQueryBindCapture initBindCapture(ServerConfig serverConfig, SpiQuery query) { - if (serverConfig.isCollectQueryPlans() && !query.getType().isUpdate()) { - return new CQueryBindCapture(this, PlatformQueryPlan.getLogger(serverConfig.getDatabasePlatform().getPlatform())); - } else { - return null; - } + private SpiQueryBindCapture initBindCapture(SpiQuery query) { + return query.getType().isUpdate() ? SpiQueryBindCapture.NOOP : server.createQueryBindCapture(this); } private String location() { @@ -187,14 +182,27 @@ public class CQueryPlan { return beanType + " hash:" + planKey; } + @Override public Class getBeanType() { return beanType; } - public Set getDependentTables() { - return dependentTables; + @Override + public String getName() { + return name; } + @Override + public String getHash() { + return hash; + } + + @Override + public String getSql() { + return sql; + } + + @Override public ProfileLocation getProfileLocation() { return profileLocation; } @@ -203,8 +211,8 @@ public class CQueryPlan { return label; } - public String getName() { - return name; + public Set getDependentTables() { + return dependentTables; } public String getLocation() { @@ -242,10 +250,6 @@ public class CQueryPlan { return asOfTableCount; } - boolean isAutoTuned() { - return autoTuned; - } - /** * Return a key used in audit logging to identify the query. */ @@ -277,14 +281,6 @@ public class CQueryPlan { } } - String getHash() { - return hash; - } - - public String getSql() { - return sql; - } - SqlTree getSqlTree() { return sqlTree; } @@ -347,10 +343,10 @@ public class CQueryPlan { void captureBindForQueryPlan(CQueryPredicates predicates, long executionTimeMicros) { try { + long startNanos = System.nanoTime(); DataBindCapture capture = bindCapture(); predicates.bind(capture); - bindCapture.setBind(capture.bindCapture(), executionTimeMicros); - + bindCapture.setBind(capture.bindCapture(), executionTimeMicros, startNanos); } catch (SQLException e) { logger.error("Error capturing bind values", e); } diff --git a/src/main/java/io/ebeaninternal/server/query/CQueryPlanManager.java b/src/main/java/io/ebeaninternal/server/query/CQueryPlanManager.java new file mode 100644 index 000000000..9ef20ed78 --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/query/CQueryPlanManager.java @@ -0,0 +1,22 @@ +package io.ebeaninternal.server.query; + +import io.ebeaninternal.api.QueryPlanManager; +import io.ebeaninternal.api.SpiQueryBindCapture; +import io.ebeaninternal.api.SpiQueryPlan; + +public class CQueryPlanManager implements QueryPlanManager { + + private final long threshold; + + private final QueryPlanLogger planLogger; + + public CQueryPlanManager(long threshold, QueryPlanLogger planLogger) { + this.threshold = threshold; + this.planLogger = planLogger; + } + + @Override + public SpiQueryBindCapture createBindCapture(SpiQueryPlan queryPlan) { + return new CQueryBindCapture(queryPlan, planLogger, threshold); + } +} diff --git a/src/main/java/io/ebeaninternal/server/query/PlatformQueryPlan.java b/src/main/java/io/ebeaninternal/server/query/PlatformQueryPlan.java deleted file mode 100644 index a0c8927f1..000000000 --- a/src/main/java/io/ebeaninternal/server/query/PlatformQueryPlan.java +++ /dev/null @@ -1,36 +0,0 @@ -package io.ebeaninternal.server.query; - -import io.ebean.annotation.Platform; - -final class PlatformQueryPlan { - - private static final QueryPlanLogger explainLogger = new QueryPlanLoggerExplain(); - - private static final QueryPlanLogger postgresLogger = new QueryPlanLoggerPostgres(); - - private static final QueryPlanLogger sqlServerLogger = new QueryPlanLoggerSqlServer(); - - private static final QueryPlanLogger oracleLogger = new QueryPlanLoggerOracle(); - - /** - * Returns the logger to log query plans for the given platform. - */ - public static QueryPlanLogger getLogger(Platform platform) { - - switch (platform) { - case POSTGRES: - return postgresLogger; - - case SQLSERVER: - case SQLSERVER16: - case SQLSERVER17: - return sqlServerLogger; - - case ORACLE: - return oracleLogger; - - default: - return explainLogger; - } - } -} diff --git a/src/main/java/io/ebeaninternal/server/query/QueryPlanLogger.java b/src/main/java/io/ebeaninternal/server/query/QueryPlanLogger.java index 52ebb6f35..3a039346a 100644 --- a/src/main/java/io/ebeaninternal/server/query/QueryPlanLogger.java +++ b/src/main/java/io/ebeaninternal/server/query/QueryPlanLogger.java @@ -1,5 +1,8 @@ package io.ebeaninternal.server.query; +import io.ebean.metric.TimedMetric; +import io.ebeaninternal.api.ExtraMetrics; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.server.type.bindcapture.BindCapture; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -12,9 +15,37 @@ public abstract class QueryPlanLogger { static final Logger queryPlanLog = LoggerFactory.getLogger(QueryPlanLogger.class); - public abstract DQueryPlanOutput logQueryPlan(Connection conn, CQueryPlan plan, BindCapture bind); + private final TimedMetric timeCollection; - DQueryPlanOutput readQueryPlan(CQueryPlan plan, BindCapture bind, ResultSet rset) throws SQLException { + private final TimedMetric timeBindCapture; + + protected QueryPlanLogger(ExtraMetrics extraMetrics) { + this.timeCollection = extraMetrics.getPlanCollect(); + this.timeBindCapture = extraMetrics.getBindCapture(); + } + + abstract DQueryPlanOutput collect(Connection conn, SpiQueryPlan plan, BindCapture bind); + + /** + * Add timing for bind capture. + */ + public void addBindTimeSince(long startNanos) { + timeBindCapture.addSinceNanos(startNanos); + } + + /** + * Collect the DB query plan. + */ + public DQueryPlanOutput collectQueryPlan(Connection conn, SpiQueryPlan plan, BindCapture bind) { + long startNanos = System.nanoTime(); + try { + return collect(conn, plan, bind); + } finally { + timeCollection.addSinceNanos(startNanos); + } + } + + DQueryPlanOutput readQueryPlan(SpiQueryPlan plan, BindCapture bind, ResultSet rset) throws SQLException { StringBuilder sb = new StringBuilder(); for (int i = 1; i <= rset.getMetaData().getColumnCount(); i++) { sb.append(rset.getMetaData().getColumnLabel(i)).append("\t"); @@ -25,11 +56,11 @@ public abstract class QueryPlanLogger { return createPlan(plan, bind.toString(), sb.toString()); } - DQueryPlanOutput createPlan(CQueryPlan plan, String bind, String planString) { + DQueryPlanOutput createPlan(SpiQueryPlan plan, String bind, String planString) { return new DQueryPlanOutput(plan.getBeanType(), plan.getName(), plan.getSql(), bind, planString, plan.getProfileLocation()); } - DQueryPlanOutput readQueryPlanBasic(CQueryPlan plan, BindCapture bind, ResultSet rset) throws SQLException { + DQueryPlanOutput readQueryPlanBasic(SpiQueryPlan plan, BindCapture bind, ResultSet rset) throws SQLException { StringBuilder sb = new StringBuilder(); readPlanData(sb, rset); return createPlan(plan, bind.toString(), sb.toString().trim()); @@ -41,7 +72,7 @@ public abstract class QueryPlanLogger { for (int i = 1; i <= rset.getMetaData().getColumnCount(); i++) { sb.append(rset.getString(i)).append("\t"); } - sb.setLength(sb.length()-1); + sb.setLength(sb.length() - 1); } } } diff --git a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerExplain.java b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerExplain.java index ee7f19f28..786c874c0 100644 --- a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerExplain.java +++ b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerExplain.java @@ -1,19 +1,25 @@ package io.ebeaninternal.server.query; +import io.ebeaninternal.api.ExtraMetrics; +import io.ebeaninternal.api.SpiQueryPlan; +import io.ebeaninternal.server.type.bindcapture.BindCapture; + import java.sql.Connection; import java.sql.PreparedStatement; import java.sql.ResultSet; import java.sql.SQLException; -import io.ebeaninternal.server.type.bindcapture.BindCapture; - /** * A QueryPlanLogger that prefixes "EXPLAIN " to the query. This works for Postgres, H2 and MySql. */ public class QueryPlanLoggerExplain extends QueryPlanLogger { + public QueryPlanLoggerExplain(ExtraMetrics extraMetrics) { + super(extraMetrics); + } + @Override - public DQueryPlanOutput logQueryPlan(Connection conn, CQueryPlan plan, BindCapture bind) { + public DQueryPlanOutput collect(Connection conn, SpiQueryPlan plan, BindCapture bind) { try (PreparedStatement explainStmt = conn.prepareStatement("EXPLAIN " + plan.getSql())) { bind.prepare(explainStmt, conn); diff --git a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerOracle.java b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerOracle.java index 48e8a860f..f4ff22025 100644 --- a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerOracle.java +++ b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerOracle.java @@ -1,6 +1,8 @@ package io.ebeaninternal.server.query; +import io.ebeaninternal.api.ExtraMetrics; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.server.type.bindcapture.BindCapture; import java.sql.Connection; @@ -16,8 +18,12 @@ import java.sql.Statement; */ public class QueryPlanLoggerOracle extends QueryPlanLogger { + public QueryPlanLoggerOracle(ExtraMetrics extraMetrics) { + super(extraMetrics); + } + @Override - public DQueryPlanOutput logQueryPlan(Connection conn, CQueryPlan plan, BindCapture bind) { + public DQueryPlanOutput collect(Connection conn, SpiQueryPlan plan, BindCapture bind) { try (Statement stmt = conn.createStatement()) { try (PreparedStatement explainStmt = conn.prepareStatement("EXPLAIN PLAN FOR " + plan.getSql())) { diff --git a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerPostgres.java b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerPostgres.java index 5b5cbf887..b36ed011c 100644 --- a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerPostgres.java +++ b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerPostgres.java @@ -1,5 +1,7 @@ package io.ebeaninternal.server.query; +import io.ebeaninternal.api.ExtraMetrics; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.server.type.bindcapture.BindCapture; import java.sql.Connection; @@ -12,8 +14,12 @@ import java.sql.SQLException; */ public class QueryPlanLoggerPostgres extends QueryPlanLogger { + public QueryPlanLoggerPostgres(ExtraMetrics extraMetrics) { + super(extraMetrics); + } + @Override - public DQueryPlanOutput logQueryPlan(Connection conn, CQueryPlan plan, BindCapture bind) { + public DQueryPlanOutput collect(Connection conn, SpiQueryPlan plan, BindCapture bind) { String explain = "explain analyze " + plan.getSql(); try (PreparedStatement explainStmt = conn.prepareStatement(explain)) { diff --git a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerSqlServer.java b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerSqlServer.java index e3e402f97..90afa320b 100644 --- a/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerSqlServer.java +++ b/src/main/java/io/ebeaninternal/server/query/QueryPlanLoggerSqlServer.java @@ -1,5 +1,7 @@ package io.ebeaninternal.server.query; +import io.ebeaninternal.api.ExtraMetrics; +import io.ebeaninternal.api.SpiQueryPlan; import io.ebeaninternal.server.type.bindcapture.BindCapture; import java.sql.Connection; @@ -16,8 +18,12 @@ import java.sql.Statement; */ public class QueryPlanLoggerSqlServer extends QueryPlanLogger { + public QueryPlanLoggerSqlServer(ExtraMetrics extraMetrics) { + super(extraMetrics); + } + @Override - public DQueryPlanOutput logQueryPlan(Connection conn, CQueryPlan plan, BindCapture bind) { + public DQueryPlanOutput collect(Connection conn, SpiQueryPlan plan, BindCapture bind) { try (Statement stmt = conn.createStatement()) { stmt.execute("set statistics xml on"); diff --git a/src/test/java/io/ebean/config/ServerConfigTest.java b/src/test/java/io/ebean/config/ServerConfigTest.java index c9c20d6d5..b54851686 100644 --- a/src/test/java/io/ebean/config/ServerConfigTest.java +++ b/src/test/java/io/ebean/config/ServerConfigTest.java @@ -72,7 +72,7 @@ public class ServerConfigTest { props.setProperty("enabledL2Regions", "r0,users,orgs"); props.setProperty("caseSensitiveCollation", "false"); props.setProperty("loadModuleInfo", "true"); - + props.setProperty("collectQueryPlanThresholdMicros", "10000"); serverConfig.loadFromProperties(props); @@ -93,6 +93,7 @@ public class ServerConfigTest { assertEquals(PlatformConfig.DbUuid.BINARY, serverConfig.getPlatformConfig().getDbUuid()); assertEquals(JsonConfig.DateTime.MILLIS, serverConfig.getJsonDateTime()); assertEquals(JsonConfig.Date.MILLIS, serverConfig.getJsonDate()); + assertEquals(10000, serverConfig.getCollectQueryPlanThresholdMicros()); assertEquals("r0,users,orgs", serverConfig.getEnabledL2Regions()); @@ -138,6 +139,7 @@ public class ServerConfigTest { assertEquals(JsonConfig.Date.ISO8601, serverConfig.getJsonDate()); assertTrue(serverConfig.getPlatformConfig().isCaseSensitiveCollation()); assertFalse(serverConfig.isAutoLoadModuleInfo()); + assertEquals(Long.MAX_VALUE, serverConfig.getCollectQueryPlanThresholdMicros()); } @Test diff --git a/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java b/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java index 0009d202f..1b7f209e5 100644 --- a/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java +++ b/src/test/java/io/ebeaninternal/api/TDSpiEbeanServer.java @@ -974,4 +974,9 @@ public class TDSpiEbeanServer implements SpiEbeanServer { public Set checkUniqueness(Object bean, Transaction transaction) { return Collections.emptySet(); } + + @Override + public SpiQueryBindCapture createQueryBindCapture(SpiQueryPlan queryPlan) { + return null; + } } diff --git a/src/test/java/org/tests/query/finder/TestCustomerFinder.java b/src/test/java/org/tests/query/finder/TestCustomerFinder.java index 6bba1f694..2423206e7 100644 --- a/src/test/java/org/tests/query/finder/TestCustomerFinder.java +++ b/src/test/java/org/tests/query/finder/TestCustomerFinder.java @@ -190,8 +190,9 @@ public class TestCustomerFinder extends BaseTestCase { } QueryPlanRequest request = new QueryPlanRequest(); - List plans = server().getMetaInfoManager().collectQueryPlans(request); + assertThat(plans).isNotEmpty(); + for (MetaQueryPlan plan : plans) { System.out.println(plan); } diff --git a/src/test/resources/ebean.properties b/src/test/resources/ebean.properties index e08f0f8a0..4caa3f7c7 100644 --- a/src/test/resources/ebean.properties +++ b/src/test/resources/ebean.properties @@ -27,7 +27,7 @@ datasource.default=h2 ebean.dumpMetricsOnShutdown=true ebean.dumpMetricsOptions=sql,hash - +ebean.collectQueryPlanThresholdMicros=1000 ebean.collectQueryPlans=true ebean.autoReadOnlyDataSource=true