From acca803a804d40520dedcb5f1b2b5cba1c55d548 Mon Sep 17 00:00:00 2001 From: Rob Bygrave Date: Wed, 22 Jan 2014 01:05:22 +1300 Subject: [PATCH] Add MetaObjectGraphNodeStats and MetaQueryPlanOriginCount etc --- .../com/avaje/ebean/bean/ObjectGraphNode.java | 2 +- .../avaje/ebean/bean/ObjectGraphOrigin.java | 2 +- .../com/avaje/ebean/config/ServerConfig.java | 53 ++++++++ .../com/avaje/ebean/meta/MetaBeanInfo.java | 4 +- .../com/avaje/ebean/meta/MetaInfoManager.java | 15 ++- .../ebean/meta/MetaObjectGraphNodeStats.java | 41 ++++++ .../ebean/meta/MetaQueryPlanOriginCount.java | 33 +++++ ...istic.java => MetaQueryPlanStatistic.java} | 20 ++- .../ebeaninternal/api/SpiEbeanServer.java | 8 ++ .../server/core/BeanRequest.java | 4 + .../core/CObjectGraphNodeStatistics.java | 89 +++++++++++++ .../server/core/DefaultMetaInfoManager.java | 21 ++- .../server/core/DefaultServer.java | 47 ++++++- .../server/deploy/BeanDescriptor.java | 10 +- .../server/loadcontext/DLoadContext.java | 4 +- .../ebeaninternal/server/query/CQuery.java | 15 ++- .../server/query/CQueryBuilder.java | 6 +- .../server/query/CQueryPlan.java | 64 +++++---- .../server/query/CQueryPlanRawSql.java | 2 +- .../server/query/CQueryPlanStats.java | 121 ++++++++++++++++-- .../query/RawSqlSelectClauseBuilder.java | 2 +- .../tests/batchload/TestLoadOnDirty.java | 1 + .../TestObjectGraphNodeStatsCollection.java | 114 +++++++++++++++++ .../tests/rawsql/TestRawSqlOrmQuery.java | 5 + 24 files changed, 609 insertions(+), 74 deletions(-) create mode 100644 src/main/java/com/avaje/ebean/meta/MetaObjectGraphNodeStats.java create mode 100644 src/main/java/com/avaje/ebean/meta/MetaQueryPlanOriginCount.java rename src/main/java/com/avaje/ebean/meta/{MetaBeanQueryPlanStatistic.java => MetaQueryPlanStatistic.java} (77%) create mode 100644 src/main/java/com/avaje/ebeaninternal/server/core/CObjectGraphNodeStatistics.java create mode 100644 src/test/java/com/avaje/tests/query/other/TestObjectGraphNodeStatsCollection.java diff --git a/src/main/java/com/avaje/ebean/bean/ObjectGraphNode.java b/src/main/java/com/avaje/ebean/bean/ObjectGraphNode.java index 8cfd0e361..0febcd36a 100644 --- a/src/main/java/com/avaje/ebean/bean/ObjectGraphNode.java +++ b/src/main/java/com/avaje/ebean/bean/ObjectGraphNode.java @@ -65,7 +65,7 @@ public final class ObjectGraphNode implements Serializable { } public String toString() { - return "origin:" + originQueryPoint + " " + ":" + path + ":" + path; + return "origin:" + originQueryPoint + " path[" + path+"]"; } public int hashCode() { diff --git a/src/main/java/com/avaje/ebean/bean/ObjectGraphOrigin.java b/src/main/java/com/avaje/ebean/bean/ObjectGraphOrigin.java index d94487df7..f5259f412 100644 --- a/src/main/java/com/avaje/ebean/bean/ObjectGraphOrigin.java +++ b/src/main/java/com/avaje/ebean/bean/ObjectGraphOrigin.java @@ -58,7 +58,7 @@ public final class ObjectGraphOrigin implements Serializable { } public String toString() { - return key + " " + beanType + " " + callStack.getFirstStackTraceElement(); + return "key["+ key + "] type[" + beanType + "] " + callStack.getFirstStackTraceElement()+" "; } public int hashCode() { diff --git a/src/main/java/com/avaje/ebean/config/ServerConfig.java b/src/main/java/com/avaje/ebean/config/ServerConfig.java index 6f5445fa1..0ef43cdd0 100644 --- a/src/main/java/com/avaje/ebean/config/ServerConfig.java +++ b/src/main/java/com/avaje/ebean/config/ServerConfig.java @@ -18,6 +18,7 @@ import com.avaje.ebean.event.BeanQueryAdapter; import com.avaje.ebean.event.BulkTableEventListener; import com.avaje.ebean.event.ServerConfigStartup; import com.avaje.ebean.event.TransactionEventListener; +import com.avaje.ebean.meta.MetaInfoManager; import com.avaje.ebean.util.ClassUtil; /** @@ -191,6 +192,10 @@ public class ServerConfig { private ServerCacheManager serverCacheManager; + private boolean collectQueryStatsByNode; + + private boolean collectQueryOrigins; + /** * Construct a Server Configuration for programmatically creating an * EbeanServer. @@ -926,6 +931,51 @@ public class ServerConfig { public void setUpdateChangesOnly(boolean updateChangesOnly) { this.updateChangesOnly = updateChangesOnly; } + + + /** + * Return true if the ebeanServer should collection query statistics by ObjectGraphNode. + */ + public boolean isCollectQueryStatsByNode() { + return collectQueryStatsByNode; + } + + /** + * Set to true to collection query execution statistics by ObjectGraphNode. + *

+ * These statistics can be used to highlight code/query 'origin points' that result in lots of lazy loading. + *

+ *

+ * It is considered safe/fine to have this set to true for production. + *

+ *

+ * This information can be later retrieved via {@link MetaInfoManager}. + *

+ * @see MetaInfoManager + */ + public void setCollectQueryStatsByNode(boolean collectQueryStatsByNode) { + this.collectQueryStatsByNode = collectQueryStatsByNode; + } + + /** + * Return true if query plans should also collect their 'origins'. This means for a given query plan you + * can identify the code/origin points where this query resulted from including lazy loading origins. + */ + public boolean isCollectQueryOrigins() { + return collectQueryOrigins; + } + + /** + * Set to true if query plans should collect their 'origin' points. This means for a given query plan you + * can identify the code/origin points where this query resulted from including lazy loading origins. + *

+ * This information can be later retrieved via {@link MetaInfoManager}. + *

+ * @see MetaInfoManager + */ + public void setCollectQueryOrigins(boolean collectQueryOrigins) { + this.collectQueryOrigins = collectQueryOrigins; + } /** * Returns the resource directory. @@ -1183,6 +1233,9 @@ public class ServerConfig { packages = getSearchJarsPackages(packagesProp); } + collectQueryStatsByNode = p.getBoolean("collectQueryStatsByNode", true); + collectQueryOrigins = p.getBoolean("collectQueryOrigins", true); + updateChangesOnly = p.getBoolean("updateChangesOnly", true); boolean batchMode = p.getBoolean("batch.mode", false); diff --git a/src/main/java/com/avaje/ebean/meta/MetaBeanInfo.java b/src/main/java/com/avaje/ebean/meta/MetaBeanInfo.java index b991582e0..dbe181154 100644 --- a/src/main/java/com/avaje/ebean/meta/MetaBeanInfo.java +++ b/src/main/java/com/avaje/ebean/meta/MetaBeanInfo.java @@ -7,11 +7,11 @@ public interface MetaBeanInfo { /** * Collect the current query plan statistics return the non-empty statistics. */ - public List collectQueryPlanStatistics(boolean reset); + public List collectQueryPlanStatistics(boolean reset); /** * Collect the current query plan statistics return all the statistics (include query plans that haven't had query executions). */ - public List collectAllQueryPlanStatistics(boolean reset); + public List collectAllQueryPlanStatistics(boolean reset); } diff --git a/src/main/java/com/avaje/ebean/meta/MetaInfoManager.java b/src/main/java/com/avaje/ebean/meta/MetaInfoManager.java index aa3ee1f4c..92724dfda 100644 --- a/src/main/java/com/avaje/ebean/meta/MetaInfoManager.java +++ b/src/main/java/com/avaje/ebean/meta/MetaInfoManager.java @@ -21,6 +21,19 @@ public interface MetaInfoManager { * executions (since the last collection with reset). *

*/ - public List collectQueryPlanStatistics(boolean reset); + public List collectQueryPlanStatistics(boolean reset); + + /** + * Collect and return the ObjectGraphNode statistics. + *

+ * These show query executions for based on an origin point and paths. This is + * used to look at the amount of lazy loading occurring for a given query + * origin point. + *

+ * + * @param reset + * Set to true to reset the underlying statistics after collection. + */ + public List collectNodeStatistics(boolean reset); } diff --git a/src/main/java/com/avaje/ebean/meta/MetaObjectGraphNodeStats.java b/src/main/java/com/avaje/ebean/meta/MetaObjectGraphNodeStats.java new file mode 100644 index 000000000..c9d4ea5df --- /dev/null +++ b/src/main/java/com/avaje/ebean/meta/MetaObjectGraphNodeStats.java @@ -0,0 +1,41 @@ +package com.avaje.ebean.meta; + +import com.avaje.ebean.bean.ObjectGraphNode; + +/** + * Statistics for query execution based on object graph origin and paths. + *

+ * These statistics can be used to identify origin queries that result in lots + * of lazy loading. + *

+ * + * @see MetaInfoManager#collectNodeStatistics(boolean) + */ +public interface MetaObjectGraphNodeStats { + + /** + * Return the ObjectGraphNode which has the origin point and relative path. + */ + public ObjectGraphNode getNode(); + + /** + * Return the startTime of statistics collection. + */ + public long getStartTime(); + + /** + * Return the total count of queries executed for this node. + */ + public long getCount(); + + /** + * Return the total time of queries executed for this node. + */ + public long getTotalTime(); + + /** + * Return the total beans loaded by queries for this node. + */ + public long getTotalBeans(); + +} \ No newline at end of file diff --git a/src/main/java/com/avaje/ebean/meta/MetaQueryPlanOriginCount.java b/src/main/java/com/avaje/ebean/meta/MetaQueryPlanOriginCount.java new file mode 100644 index 000000000..ee53702c8 --- /dev/null +++ b/src/main/java/com/avaje/ebean/meta/MetaQueryPlanOriginCount.java @@ -0,0 +1,33 @@ +package com.avaje.ebean.meta; + +import com.avaje.ebean.bean.ObjectGraphNode; + +/** + * Holds a query 'origin' point and count for the number of queries executed for + * this 'origin'. + *

+ * This basically points to the bit of original code and query that results in + * this query directly or via lazy loading. + *

+ * + * @see MetaQueryPlanStatistic + * @see MetaInfoManager#collectQueryPlanStatistics(boolean) + */ +public interface MetaQueryPlanOriginCount { + + /** + * The 'origin' and path which this query belongs to. + *

+ * For lazy loading queries this points to the original query and associated + * navigation path that resulted in this query being executed. + *

+ */ + public ObjectGraphNode getObjectGraphNode(); + + /** + * The number of times a query was fired for this node since the counter was + * last reset. + */ + public long getCount(); + +} \ No newline at end of file diff --git a/src/main/java/com/avaje/ebean/meta/MetaBeanQueryPlanStatistic.java b/src/main/java/com/avaje/ebean/meta/MetaQueryPlanStatistic.java similarity index 77% rename from src/main/java/com/avaje/ebean/meta/MetaBeanQueryPlanStatistic.java rename to src/main/java/com/avaje/ebean/meta/MetaQueryPlanStatistic.java index 1b4ffe9a1..d680a15a9 100644 --- a/src/main/java/com/avaje/ebean/meta/MetaBeanQueryPlanStatistic.java +++ b/src/main/java/com/avaje/ebean/meta/MetaQueryPlanStatistic.java @@ -1,15 +1,19 @@ package com.avaje.ebean.meta; +import java.util.List; + /** * Query execution statistics Meta data. + * + * @see MetaInfoManager#collectQueryPlanStatistics(boolean) */ -public interface MetaBeanQueryPlanStatistic { +public interface MetaQueryPlanStatistic { /** * Return the bean type this query plan is for. */ public Class getBeanType(); - + /** * Return true if this query plan was tuned by Autofetch. */ @@ -47,7 +51,7 @@ public interface MetaBeanQueryPlanStatistic { * Return the max execution time for this query. */ public long getMaxTimeMicros(); - + /** * Return the time collection started (or was last reset). */ @@ -74,4 +78,14 @@ public interface MetaBeanQueryPlanStatistic { */ public long getAvgLoadedBeans(); + /** + * Return the 'origin' points and paths that resulted in the query being + * executed and the associated number of times the query was executed via that + * path. + *

+ * This includes direct and lazy loading paths. + *

+ */ + public List getOrigins(); + } diff --git a/src/main/java/com/avaje/ebeaninternal/api/SpiEbeanServer.java b/src/main/java/com/avaje/ebeaninternal/api/SpiEbeanServer.java index 98ecd2db9..c148f2e51 100644 --- a/src/main/java/com/avaje/ebeaninternal/api/SpiEbeanServer.java +++ b/src/main/java/com/avaje/ebeaninternal/api/SpiEbeanServer.java @@ -9,6 +9,7 @@ import com.avaje.ebean.TxScope; import com.avaje.ebean.bean.BeanCollectionLoader; import com.avaje.ebean.bean.BeanLoader; import com.avaje.ebean.bean.CallStack; +import com.avaje.ebean.bean.ObjectGraphNode; import com.avaje.ebean.config.dbplatform.DatabasePlatform; import com.avaje.ebeaninternal.server.autofetch.AutoFetchManager; import com.avaje.ebeaninternal.server.core.PstmtBatch; @@ -29,6 +30,8 @@ public interface SpiEbeanServer extends EbeanServer, BeanLoader, BeanCollectionL */ public void shutdownManaged(); + public boolean isCollectQueryOrigins(); + /** * Return true if DeleteMissingChildren defaults to true for stateless * updates. @@ -187,4 +190,9 @@ public interface SpiEbeanServer extends EbeanServer, BeanLoader, BeanCollectionL */ public boolean isSupportedType(java.lang.reflect.Type genericType); + /** + * Collect query statistics by ObjectGraphNode. Used for Lazy loading reporting. + */ + public void collectQueryStats(ObjectGraphNode objectGraphNode, long loadedBeanCount, long timeMicros); + } diff --git a/src/main/java/com/avaje/ebeaninternal/server/core/BeanRequest.java b/src/main/java/com/avaje/ebeaninternal/server/core/BeanRequest.java index b6a2d599b..f3378df7b 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/core/BeanRequest.java +++ b/src/main/java/com/avaje/ebeaninternal/server/core/BeanRequest.java @@ -96,6 +96,10 @@ public abstract class BeanRequest { return ebeanServer; } + public SpiEbeanServer getServer() { + return ebeanServer; + } + /** * Return the Transaction associated with this request. */ diff --git a/src/main/java/com/avaje/ebeaninternal/server/core/CObjectGraphNodeStatistics.java b/src/main/java/com/avaje/ebeaninternal/server/core/CObjectGraphNodeStatistics.java new file mode 100644 index 000000000..9b223b2d0 --- /dev/null +++ b/src/main/java/com/avaje/ebeaninternal/server/core/CObjectGraphNodeStatistics.java @@ -0,0 +1,89 @@ +package com.avaje.ebeaninternal.server.core; + +import java.util.concurrent.atomic.AtomicLong; + +import com.avaje.ebean.meta.*; +import com.avaje.ebean.bean.ObjectGraphNode; +import com.avaje.ebeaninternal.server.util.LongAdder; + +/** + * Helper to collect the query execution statistics for a given node. + */ +public class CObjectGraphNodeStatistics { + + private final ObjectGraphNode node; + + private final LongAdder count = new LongAdder(); + + private final LongAdder totalTime = new LongAdder(); + + private final LongAdder totalBeans = new LongAdder(); + + private final AtomicLong startTime = new AtomicLong(System.currentTimeMillis()); + + public CObjectGraphNodeStatistics(ObjectGraphNode node) { + this.node = node; + } + + public void add(long beanCount, long exeMicros) { + count.increment(); + totalTime.add(exeMicros); + totalBeans.add(beanCount); + } + + public MetaObjectGraphNodeStats get(boolean reset) { + if (reset) { + return new Snapshot(node, startTime.getAndSet(System.currentTimeMillis()), count.sumThenReset(), + totalTime.sumThenReset(), totalBeans.sumThenReset()); + } else { + return new Snapshot(node, startTime.get(), count.sum(), totalTime.sum(), totalBeans.sum()); + } + } + + private static class Snapshot implements MetaObjectGraphNodeStats { + + private final ObjectGraphNode node; + private final long startTime; + private final long count; + private final long totalTime; + private final long totalBeans; + + public Snapshot(ObjectGraphNode node, long startTime, long count, long totalTime, long totalBeans) { + this.node = node; + this.startTime = startTime; + this.count = count; + this.totalTime = totalTime; + this.totalBeans = totalBeans; + } + + public String toString() { + return node + " count[" + count + "] time[" + totalTime + "] beans[" + totalBeans + "]"; + } + + @Override + public ObjectGraphNode getNode() { + return node; + } + + @Override + public long getStartTime() { + return startTime; + } + + @Override + public long getCount() { + return count; + } + + @Override + public long getTotalTime() { + return totalTime; + } + + @Override + public long getTotalBeans() { + return totalBeans; + } + } + +} diff --git a/src/main/java/com/avaje/ebeaninternal/server/core/DefaultMetaInfoManager.java b/src/main/java/com/avaje/ebeaninternal/server/core/DefaultMetaInfoManager.java index 5facae4a2..d0fd38992 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/core/DefaultMetaInfoManager.java +++ b/src/main/java/com/avaje/ebeaninternal/server/core/DefaultMetaInfoManager.java @@ -4,8 +4,9 @@ import java.util.ArrayList; import java.util.List; import com.avaje.ebean.meta.MetaBeanInfo; -import com.avaje.ebean.meta.MetaBeanQueryPlanStatistic; +import com.avaje.ebean.meta.MetaQueryPlanStatistic; import com.avaje.ebean.meta.MetaInfoManager; +import com.avaje.ebean.meta.MetaObjectGraphNodeStats; /** * DefaultServer based implementation of MetaInfoManager. @@ -30,9 +31,9 @@ public class DefaultMetaInfoManager implements MetaInfoManager { } @Override - public List collectQueryPlanStatistics(boolean reset) { + public List collectQueryPlanStatistics(boolean reset) { - List list = new ArrayList(); + List list = new ArrayList(); for (MetaBeanInfo metaBeanInfo : getMetaBeanInfoList()) { list.addAll(metaBeanInfo.collectQueryPlanStatistics(reset)); @@ -41,4 +42,18 @@ public class DefaultMetaInfoManager implements MetaInfoManager { return list; } + public List collectNodeStatistics(boolean reset) { + + List list = new ArrayList(); + + for (CObjectGraphNodeStatistics nodeStatistics : server.objectGraphStats.values()) { + MetaObjectGraphNodeStats nodeStats = nodeStatistics.get(reset); + if (nodeStats.getCount() > 0) { + // Only collection non-empty statistics + list.add(nodeStats); + } + } + return list; + } + } diff --git a/src/main/java/com/avaje/ebeaninternal/server/core/DefaultServer.java b/src/main/java/com/avaje/ebeaninternal/server/core/DefaultServer.java index 45f2d1eba..1a3e5c355 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/core/DefaultServer.java +++ b/src/main/java/com/avaje/ebeaninternal/server/core/DefaultServer.java @@ -9,6 +9,7 @@ import java.util.List; import java.util.Map; import java.util.ServiceLoader; import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.FutureTask; import javax.management.InstanceAlreadyExistsException; @@ -49,11 +50,13 @@ import com.avaje.ebean.bean.BeanCollection; import com.avaje.ebean.bean.CallStack; import com.avaje.ebean.bean.EntityBean; import com.avaje.ebean.bean.EntityBeanIntercept; +import com.avaje.ebean.bean.ObjectGraphNode; import com.avaje.ebean.bean.PersistenceContext; import com.avaje.ebean.bean.PersistenceContext.WithOption; import com.avaje.ebean.cache.ServerCacheManager; import com.avaje.ebean.config.EncryptKeyManager; import com.avaje.ebean.config.GlobalProperties; +import com.avaje.ebean.config.ServerConfig; import com.avaje.ebean.config.dbplatform.DatabasePlatform; import com.avaje.ebean.event.BeanPersistController; import com.avaje.ebean.event.BeanQueryAdapter; @@ -207,26 +210,41 @@ public final class DefaultServer implements SpiEbeanServer { */ private List ebeanPlugins; + private final boolean collectQueryOrigins; + + private final boolean collectQueryStatsByNode; + + /** + * Cache used to collect statistics based on ObjectGraphNode (used to highlight lazy loading origin points). + */ + protected final ConcurrentHashMap objectGraphStats; + /** * Create the DefaultServer. */ public DefaultServer(InternalConfiguration config, ServerCacheManager cache) { + ServerConfig serverConfig = config.getServerConfig(); + + this.objectGraphStats = new ConcurrentHashMap(); this.metaInfoManager = new DefaultMetaInfoManager(this); this.serverCacheManager = cache; this.pstmtBatch = config.getPstmtBatch(); this.databasePlatform = config.getDatabasePlatform(); this.backgroundExecutor = config.getBackgroundExecutor(); - this.serverName = config.getServerConfig().getName(); - this.lazyLoadBatchSize = config.getServerConfig().getLazyLoadBatchSize(); - this.queryBatchSize = config.getServerConfig().getQueryBatchSize(); + + this.serverName = serverConfig.getName(); + this.lazyLoadBatchSize = serverConfig.getLazyLoadBatchSize(); + this.queryBatchSize = serverConfig.getQueryBatchSize(); this.cqueryEngine = config.getCQueryEngine(); this.expressionFactory = config.getExpressionFactory(); - this.encryptKeyManager = config.getServerConfig().getEncryptKeyManager(); + this.encryptKeyManager = serverConfig.getEncryptKeyManager(); this.beanDescriptorManager = config.getBeanDescriptorManager(); beanDescriptorManager.setEbeanServer(this); + this.collectQueryOrigins = serverConfig.isCollectQueryOrigins(); + this.collectQueryStatsByNode = serverConfig.isCollectQueryStatsByNode(); this.maxCallStack = GlobalProperties.getInt("ebean.maxCallStack", 5); this.defaultUpdateNullProperties = "true" @@ -284,6 +302,11 @@ public final class DefaultServer implements SpiEbeanServer { } } + @Override + public boolean isCollectQueryOrigins() { + return collectQueryOrigins; + } + public boolean isDefaultDeleteMissingChildren() { return defaultDeleteMissingChildren; } @@ -2093,4 +2116,20 @@ public final class DefaultServer implements SpiEbeanServer { return jsonContext; } + + @Override + public void collectQueryStats(ObjectGraphNode node, long loadedBeanCount, long timeMicros) { + + if (collectQueryStatsByNode) { + CObjectGraphNodeStatistics nodeStatistics = objectGraphStats.get(node); + if (nodeStatistics == null) { + // race condition here but I actually don't care too much if we miss a + // few early statistics - especially when the server is warming up etc + nodeStatistics = new CObjectGraphNodeStatistics(node); + objectGraphStats.put(node, nodeStatistics); + } + nodeStatistics.add(loadedBeanCount, timeMicros); + } + } + } diff --git a/src/main/java/com/avaje/ebeaninternal/server/deploy/BeanDescriptor.java b/src/main/java/com/avaje/ebeaninternal/server/deploy/BeanDescriptor.java index 4b6024c92..d6632d05f 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/deploy/BeanDescriptor.java +++ b/src/main/java/com/avaje/ebeaninternal/server/deploy/BeanDescriptor.java @@ -37,7 +37,7 @@ import com.avaje.ebean.event.BeanPersistController; import com.avaje.ebean.event.BeanPersistListener; import com.avaje.ebean.event.BeanQueryAdapter; import com.avaje.ebean.meta.MetaBeanInfo; -import com.avaje.ebean.meta.MetaBeanQueryPlanStatistic; +import com.avaje.ebean.meta.MetaQueryPlanStatistic; import com.avaje.ebean.text.TextException; import com.avaje.ebean.text.json.JsonWriteBeanVisitor; import com.avaje.ebeaninternal.api.HashQueryPlan; @@ -1154,17 +1154,17 @@ public class BeanDescriptor implements MetaBeanInfo { } @Override - public List collectQueryPlanStatistics(boolean reset) { + public List collectQueryPlanStatistics(boolean reset) { return collectQueryPlanStatisticsInternal(reset, false); } @Override - public List collectAllQueryPlanStatistics(boolean reset) { + public List collectAllQueryPlanStatistics(boolean reset) { return collectQueryPlanStatisticsInternal(reset, false); } - public List collectQueryPlanStatisticsInternal(boolean reset, boolean collectAll) { - List list = new ArrayList(queryPlanCache.size()); + public List collectQueryPlanStatisticsInternal(boolean reset, boolean collectAll) { + List list = new ArrayList(queryPlanCache.size()); for (CQueryPlan queryPlan : queryPlanCache.values()) { Snapshot snapshot = queryPlan.getSnapshot(reset); if (collectAll || snapshot.getExecutionCount() > 0) { diff --git a/src/main/java/com/avaje/ebeaninternal/server/loadcontext/DLoadContext.java b/src/main/java/com/avaje/ebeaninternal/server/loadcontext/DLoadContext.java index 71a7e2189..3d162083a 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/loadcontext/DLoadContext.java +++ b/src/main/java/com/avaje/ebeaninternal/server/loadcontext/DLoadContext.java @@ -64,7 +64,6 @@ public class DLoadContext implements LoadContext { this.ebeanServer = ebeanServer; this.defaultBatchSize = ebeanServer.getLazyLoadBatchSize(); this.rootDescriptor = rootDescriptor; - this.rootBeanContext = new DLoadBeanContext(this, rootDescriptor, null, defaultBatchSize, null); this.readOnly = readOnly; this.excludeBeanCache = excludeBeanCache; this.useAutofetchManager = useAutofetchManager; @@ -76,6 +75,9 @@ public class DLoadContext implements LoadContext { this.origin = null; this.relativePath = null; } + + // initialise rootBeanContext after origin and relativePath have been set + this.rootBeanContext = new DLoadBeanContext(this, rootDescriptor, null, defaultBatchSize, null); } protected boolean isExcludeBeanCache() { diff --git a/src/main/java/com/avaje/ebeaninternal/server/query/CQuery.java b/src/main/java/com/avaje/ebeaninternal/server/query/CQuery.java index cdbe59e29..8904cbb55 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/query/CQuery.java +++ b/src/main/java/com/avaje/ebeaninternal/server/query/CQuery.java @@ -10,6 +10,9 @@ import java.util.concurrent.TimeUnit; import javax.persistence.PersistenceException; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + import com.avaje.ebean.QueryIterator; import com.avaje.ebean.QueryListener; import com.avaje.ebean.bean.BeanCollection; @@ -21,6 +24,7 @@ import com.avaje.ebean.bean.NodeUsageListener; import com.avaje.ebean.bean.ObjectGraphNode; import com.avaje.ebean.bean.PersistenceContext; import com.avaje.ebeaninternal.api.LoadContext; +import com.avaje.ebeaninternal.api.SpiEbeanServer; import com.avaje.ebeaninternal.api.SpiExpressionList; import com.avaje.ebeaninternal.api.SpiQuery; import com.avaje.ebeaninternal.api.SpiQuery.Mode; @@ -41,9 +45,6 @@ import com.avaje.ebeaninternal.server.transaction.DefaultPersistenceContext; import com.avaje.ebeaninternal.server.type.DataBind; import com.avaje.ebeaninternal.server.type.DataReader; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; - /** * An object that represents a SqlSelect statement. *

@@ -210,7 +211,7 @@ public class CQuery implements DbReadContext, CancelableQuery { private final boolean autoFetchProfiling; - private final ObjectGraphNode autoFetchParentNode; + private final ObjectGraphNode objectGraphNode; private final AutoFetchManager autoFetchManager; @@ -238,7 +239,7 @@ public class CQuery implements DbReadContext, CancelableQuery { this.autoFetchManager = query.getAutoFetchManager(); this.autoFetchProfiling = autoFetchManager != null; - this.autoFetchParentNode = autoFetchProfiling ? query.getParentNode() : null; + this.objectGraphNode = query.getParentNode(); this.autoFetchManagerRef = autoFetchProfiling ? new WeakReference( autoFetchManager) : null; @@ -645,9 +646,9 @@ public class CQuery implements DbReadContext, CancelableQuery { if (autoFetchProfiling) { autoFetchManager - .collectQueryInfo(autoFetchParentNode, loadedBeanCount, executionTimeMicros); + .collectQueryInfo(objectGraphNode, loadedBeanCount, executionTimeMicros); } - queryPlan.executionTime(loadedBeanCount, executionTimeMicros); + queryPlan.executionTime(loadedBeanCount, executionTimeMicros, objectGraphNode); } catch (Exception e) { logger.error(null, e); diff --git a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryBuilder.java b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryBuilder.java index d968faf96..438853c3e 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryBuilder.java +++ b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryBuilder.java @@ -115,7 +115,7 @@ public class CQueryBuilder implements Constants { String sql = s.getSql(); // cache the query plan - queryPlan = new CQueryPlan(query.getBeanType(), sql, sqlTree, false, s.isIncludesRowNumberColumn(), predicates.getLogWhereSql()); + queryPlan = new CQueryPlan(request, sql, sqlTree, false, s.isIncludesRowNumberColumn(), predicates.getLogWhereSql()); request.putQueryPlan(queryPlan); return new CQueryFetchIds(request, predicates, sql, backgroundExecutor); @@ -171,7 +171,7 @@ public class CQueryBuilder implements Constants { } // cache the query plan - queryPlan = new CQueryPlan(query.getBeanType(), sql, sqlTree, false, s.isIncludesRowNumberColumn(), predicates.getLogWhereSql()); + queryPlan = new CQueryPlan(request, sql, sqlTree, false, s.isIncludesRowNumberColumn(), predicates.getLogWhereSql()); request.putQueryPlan(queryPlan); return new CQueryRowCount(request, predicates, sql); @@ -216,7 +216,7 @@ public class CQueryBuilder implements Constants { queryPlan = new CQueryPlanRawSql(request, res, sqlTree, predicates.getLogWhereSql()); } else { - queryPlan = new CQueryPlan(request, res, sqlTree, rawSql, predicates.getLogWhereSql(), null); + queryPlan = new CQueryPlan(request, res, sqlTree, rawSql, predicates.getLogWhereSql()); } // cache the query plan because we can reuse it and also diff --git a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlan.java b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlan.java index 526ce1e42..e66cb464a 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlan.java +++ b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlan.java @@ -3,9 +3,11 @@ package com.avaje.ebeaninternal.server.query; import java.sql.ResultSet; import java.sql.SQLException; +import com.avaje.ebean.bean.ObjectGraphNode; import com.avaje.ebean.config.dbplatform.SqlLimitResponse; import com.avaje.ebeaninternal.api.HashQueryPlan; import com.avaje.ebeaninternal.api.HashQueryPlanBuilder; +import com.avaje.ebeaninternal.api.SpiEbeanServer; import com.avaje.ebeaninternal.server.core.OrmQueryRequest; import com.avaje.ebeaninternal.server.deploy.BeanProperty; import com.avaje.ebeaninternal.server.query.CQueryPlanStats.Snapshot; @@ -34,6 +36,8 @@ import com.avaje.ebeaninternal.server.type.RsetDataReader; */ public class CQueryPlan { + private final SpiEbeanServer server; + private final boolean autofetchTuned; private final HashQueryPlan hash; @@ -60,34 +64,35 @@ public class CQueryPlan { /** * Create a query plan based on a OrmQueryRequest. */ - public CQueryPlan(OrmQueryRequest request, SqlLimitResponse sqlRes, SqlTree sqlTree, - boolean rawSql, String logWhereSql, String luceneQueryDescription) { - - this.beanType = request.getBeanDescriptor().getBeanType(); - this.stats = new CQueryPlanStats(this); - this.hash = request.getQueryPlanHash(); - this.autofetchTuned = request.getQuery().isAutofetchTuned(); - if (sqlRes != null){ - this.sql = sqlRes.getSql(); - this.rowNumberIncluded = sqlRes.isIncludesRowNumberColumn(); - } else { - this.sql = luceneQueryDescription; - this.rowNumberIncluded = false; - } - this.sqlTree = sqlTree; - this.rawSql = rawSql; - this.logWhereSql = logWhereSql; - this.encryptedProps = sqlTree.getEncryptedProps(); - } + public CQueryPlan(OrmQueryRequest request, SqlLimitResponse sqlRes, SqlTree sqlTree, boolean rawSql, String logWhereSql) { + + this.server = request.getServer(); + this.beanType = request.getBeanDescriptor().getBeanType(); + this.stats = new CQueryPlanStats(this, server.isCollectQueryOrigins()); + this.hash = request.getQueryPlanHash(); + this.autofetchTuned = request.getQuery().isAutofetchTuned(); + if (sqlRes != null) { + this.sql = sqlRes.getSql(); + this.rowNumberIncluded = sqlRes.isIncludesRowNumberColumn(); + } else { + this.sql = null; + this.rowNumberIncluded = false; + } + this.sqlTree = sqlTree; + this.rawSql = rawSql; + this.logWhereSql = logWhereSql; + this.encryptedProps = sqlTree.getEncryptedProps(); + } /** * Create a query plan for a raw sql query. */ - public CQueryPlan(Class beanType, String sql, SqlTree sqlTree, + public CQueryPlan(OrmQueryRequest request, String sql, SqlTree sqlTree, boolean rawSql, boolean rowNumberIncluded, String logWhereSql) { - - this.beanType = beanType; - this.stats = new CQueryPlanStats(this); + + this.server = request.getServer(); + this.beanType = request.getBeanDescriptor().getBeanType(); + this.stats = new CQueryPlanStats(this, server.isCollectQueryOrigins()); this.hash = buildHash(sql, rawSql, rowNumberIncluded, logWhereSql); this.autofetchTuned = false; this.sql = sql; @@ -97,8 +102,9 @@ public class CQueryPlan { this.logWhereSql = logWhereSql; this.encryptedProps = sqlTree.getEncryptedProps(); } - - private HashQueryPlan buildHash(String sql, boolean rawSql, boolean rowNumberIncluded, String logWhereSql) { + + + private HashQueryPlan buildHash(String sql, boolean rawSql, boolean rowNumberIncluded, String logWhereSql) { HashQueryPlanBuilder builder = new HashQueryPlanBuilder(); builder.add(sql).add(rawSql).add(rowNumberIncluded).add(logWhereSql); builder.addRawSql(sql); @@ -165,9 +171,13 @@ public class CQueryPlan { /** * Register an execution time against this query plan; */ - public void executionTime(long loadedBeanCount, long timeMicros) { + public void executionTime(long loadedBeanCount, long timeMicros, ObjectGraphNode objectGraphNode) { - stats.add(loadedBeanCount, timeMicros); + stats.add(loadedBeanCount, timeMicros, objectGraphNode); + if (objectGraphNode != null) { + // collect stats based on objectGraphNode for lazy loading reporting + server.collectQueryStats(objectGraphNode, loadedBeanCount, timeMicros); + } } public Snapshot getSnapshot(boolean reset) { diff --git a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanRawSql.java b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanRawSql.java index 696d0b02f..4fcc496df 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanRawSql.java +++ b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanRawSql.java @@ -15,7 +15,7 @@ public class CQueryPlanRawSql extends CQueryPlan { public CQueryPlanRawSql(OrmQueryRequest request, SqlLimitResponse sqlRes, SqlTree sqlTree, String logWhereSql) { - super(request, sqlRes, sqlTree, true, logWhereSql, null); + super(request, sqlRes, sqlTree, true, logWhereSql); this.rsetIndexPositions = createIndexPositions(request, sqlTree); } diff --git a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanStats.java b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanStats.java index 72de23d8c..5e434be17 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanStats.java +++ b/src/main/java/com/avaje/ebeaninternal/server/query/CQueryPlanStats.java @@ -1,9 +1,17 @@ package com.avaje.ebeaninternal.server.query; +import java.util.ArrayList; +import java.util.Collection; +import java.util.Collections; +import java.util.List; +import java.util.Map.Entry; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.atomic.AtomicLong; -import com.avaje.ebean.meta.MetaBeanQueryPlanStatistic; +import com.avaje.ebean.bean.ObjectGraphNode; +import com.avaje.ebean.meta.MetaQueryPlanStatistic; +import com.avaje.ebean.meta.MetaQueryPlanOriginCount; import com.avaje.ebeaninternal.server.util.LongAdder; /** @@ -25,12 +33,14 @@ public final class CQueryPlanStats { private long lastQueryTime; - - public CQueryPlanStats(CQueryPlan queryPlan) { + private final ConcurrentHashMap origins; + + public CQueryPlanStats(CQueryPlan queryPlan, boolean collectQueryOrigins) { this.queryPlan = queryPlan; + this.origins = !collectQueryOrigins ? null : new ConcurrentHashMap(); } - public void add(long loadedBeanCount, long timeMicros) { + public void add(long loadedBeanCount, long timeMicros, ObjectGraphNode objectGraphNode) { count.increment(); totalBeans.add(loadedBeanCount); totalTime.add(timeMicros); @@ -38,15 +48,37 @@ public final class CQueryPlanStats { // effectively a high water mark maxTime.set(timeMicros); } + // not safe but should be atomic lastQueryTime = System.currentTimeMillis(); + + if (origins != null && objectGraphNode != null) { + // Maintain the origin points this query fires from + // with a simple counter + LongAdder counter = origins.get(objectGraphNode); + if (counter == null) { + // race condition - we can miss counters here but going + // to live with that. Don't want to lock/synchronize etc + counter = new LongAdder(); + origins.put(objectGraphNode, counter); + } + counter.increment(); + } } public void reset() { + // Racey but near enough for our purposes as we don't want locks count.reset(); totalBeans.reset(); totalTime.reset(); maxTime.set(0); startTime.set(System.currentTimeMillis()); + + if (origins != null) { + for (LongAdder counter : origins.values()) { + counter.reset(); + } + } + } public long getLastQueryTime() { @@ -54,17 +86,68 @@ public final class CQueryPlanStats { } public Snapshot getSnapshot(boolean reset) { - // not guaranteed to be consistent - time gaps between getting each value + + List origins = getOrigins(reset); + + // not guaranteed to be consistent due to time gaps between getting each value out of LongAdders but can live with that + // relative to the cost of making sure count and totalTime etc are all guaranteed to be consistent if (reset) { - return new Snapshot(queryPlan, count.sumThenReset(), totalTime.sumThenReset(), totalBeans.sumThenReset(), maxTime.getAndSet(0), startTime.getAndSet(System.currentTimeMillis()), lastQueryTime); + return new Snapshot(queryPlan, count.sumThenReset(), totalTime.sumThenReset(), totalBeans.sumThenReset(), maxTime.getAndSet(0), startTime.getAndSet(System.currentTimeMillis()), lastQueryTime, origins); } - return new Snapshot(queryPlan, count.sum(), totalTime.sum(), totalBeans.sum(), maxTime.get(), startTime.get(), lastQueryTime); + return new Snapshot(queryPlan, count.sum(), totalTime.sum(), totalBeans.sum(), maxTime.get(), startTime.get(), lastQueryTime, origins); } + + /** + * Return the list/snapshot of the origins and their counter value. + */ + private List getOrigins(boolean reset) { + if (origins == null) { + return Collections.emptyList(); + } + + List list = new ArrayList(); + + for (Entry entry : origins.entrySet()) { + if (reset) { + list.add(new OriginSnapshot(entry.getKey(), entry.getValue().sumThenReset())); + } else { + list.add(new OriginSnapshot(entry.getKey(), entry.getValue().sum())); + } + } + return list; + } + + /** + * Snapshot of the origin ObjectGraphNode and counter value. + */ + private static class OriginSnapshot implements MetaQueryPlanOriginCount { + private final ObjectGraphNode objectGraphNode; + private final long count; + + public OriginSnapshot(ObjectGraphNode objectGraphNode, long count) { + this.objectGraphNode = objectGraphNode; + this.count = count; + } + public String toString() { + return "node["+objectGraphNode+"] count["+count+"]"; + } + + @Override + public ObjectGraphNode getObjectGraphNode() { + return objectGraphNode; + } + + @Override + public long getCount() { + return count; + } + } + /** * A snapshot of the current statistics for a query plan. */ - public static class Snapshot implements MetaBeanQueryPlanStatistic { + public static class Snapshot implements MetaQueryPlanStatistic { private final CQueryPlan queryPlan; private final long count; @@ -73,9 +156,11 @@ public final class CQueryPlanStats { private final long maxTime; private final long startTime; private final long lastQueryTime; - - public Snapshot(CQueryPlan queryPlan, long count, long totalTime, long totalBeans, long maxTime, long startTime, long lastQueryTime) { - super(); + private final List origins; + + public Snapshot(CQueryPlan queryPlan, long count, long totalTime, long totalBeans, long maxTime, long startTime, long lastQueryTime, + List origins) { + this.queryPlan = queryPlan; this.count = count; this.totalTime = totalTime; @@ -83,11 +168,13 @@ public final class CQueryPlanStats { this.maxTime = maxTime; this.startTime = startTime; this.lastQueryTime = lastQueryTime; + this.origins = origins; } - public String toString() { - return queryPlan+" count:"+count+" time:"+totalTime+" maxTime:"+maxTime+" beans:"+totalBeans+" start:"+startTime+" lastQuery:"+lastQueryTime; - } + public String toString() { + return queryPlan + " count:" + count + " time:" + totalTime + " maxTime:" + maxTime + " beans:" + totalBeans + + " start:" + startTime + " lastQuery:" + lastQueryTime + " origins:" + origins; + } @Override public Class getBeanType() { @@ -149,6 +236,12 @@ public final class CQueryPlanStats { public long getAvgLoadedBeans() { return count < 1 ? 0 : totalBeans / count; } + + @Override + public List getOrigins() { + return origins; + } + } } \ No newline at end of file diff --git a/src/main/java/com/avaje/ebeaninternal/server/query/RawSqlSelectClauseBuilder.java b/src/main/java/com/avaje/ebeaninternal/server/query/RawSqlSelectClauseBuilder.java index 5c92b11bf..4a958f67e 100644 --- a/src/main/java/com/avaje/ebeaninternal/server/query/RawSqlSelectClauseBuilder.java +++ b/src/main/java/com/avaje/ebeaninternal/server/query/RawSqlSelectClauseBuilder.java @@ -83,7 +83,7 @@ public class RawSqlSelectClauseBuilder { SqlTree sqlTree = sqlSelect.getSqlTree(); - CQueryPlan queryPlan = new CQueryPlan(query.getBeanType(), sql, sqlTree, true, includeRowNumColumn, ""); + CQueryPlan queryPlan = new CQueryPlan(request, sql, sqlTree, true, includeRowNumColumn, ""); CQuery compiledQuery = new CQuery(request, predicates, queryPlan); return compiledQuery; diff --git a/src/test/java/com/avaje/tests/batchload/TestLoadOnDirty.java b/src/test/java/com/avaje/tests/batchload/TestLoadOnDirty.java index 025ea47f0..d008701db 100644 --- a/src/test/java/com/avaje/tests/batchload/TestLoadOnDirty.java +++ b/src/test/java/com/avaje/tests/batchload/TestLoadOnDirty.java @@ -21,6 +21,7 @@ public class TestLoadOnDirty extends BaseTestCase { List custs = Ebean.find(Customer.class).findList(); Customer customer = Ebean.find(Customer.class).setId(custs.get(0).getId()).select("name") + .setUseCache(false) .findUnique(); BeanState beanState = Ebean.getBeanState(customer); diff --git a/src/test/java/com/avaje/tests/query/other/TestObjectGraphNodeStatsCollection.java b/src/test/java/com/avaje/tests/query/other/TestObjectGraphNodeStatsCollection.java new file mode 100644 index 000000000..1bbf45019 --- /dev/null +++ b/src/test/java/com/avaje/tests/query/other/TestObjectGraphNodeStatsCollection.java @@ -0,0 +1,114 @@ +package com.avaje.tests.query.other; + +import java.util.List; + +import org.junit.Assert; +import org.junit.Test; + +import com.avaje.ebean.BaseTestCase; +import com.avaje.ebean.Ebean; +import com.avaje.ebean.EbeanServer; +import com.avaje.ebean.meta.MetaInfoManager; +import com.avaje.ebean.meta.MetaObjectGraphNodeStats; +import com.avaje.ebean.meta.MetaQueryPlanStatistic; +import com.avaje.tests.model.basic.Address; +import com.avaje.tests.model.basic.Customer; +import com.avaje.tests.model.basic.Order; +import com.avaje.tests.model.basic.OrderDetail; +import com.avaje.tests.model.basic.ResetBasicData; + +public class TestObjectGraphNodeStatsCollection extends BaseTestCase { + + @Test + public void test() { + + ResetBasicData.reset(); + + EbeanServer server = Ebean.getServer(null); + + MetaInfoManager infoManager = server.getMetaInfoManager(); + + + server.find(Order.class).findRowCount(); + + infoManager.collectNodeStatistics(true); + infoManager.collectQueryPlanStatistics(true); + + runFindOrderQuery(server); + runFindCustomerQuery(server); + + System.out.println("============================================================"); + + List nodeStatistics = infoManager.collectNodeStatistics(true); + for (MetaObjectGraphNodeStats stat : nodeStatistics) { + System.out.println("-----------"); + System.out.println(stat); + } + + System.out.println("============================================================"); + + List planStatistics = infoManager.collectQueryPlanStatistics(true); + for (MetaQueryPlanStatistic planStatistic : planStatistics) { + System.out.println("------------"); + System.out.println(planStatistic); + System.out.println(planStatistic.getSql()); + } + + System.out.println("============================================================"); + + + } + + private void runFindCustomerQuery(EbeanServer server) { + + List customers = server.find(Customer.class) + .select("name") + .fetch("contacts") + .findList(); + + Assert.assertTrue(!customers.isEmpty()); + + List custs = server.find(Customer.class).select("name").findList(); + for (Customer customer : custs) { + customer.getShippingAddress(); + } + } + + private void runFindOrderQuery(EbeanServer server) { + List orders = server.find(Order.class) + .where().gt("id", 0) + .order().asc("orderDate") + .setMaxRows(40) + .findList(); + + for (Order order : orders) { + Customer customer = order.getCustomer(); + Address billingAddress = customer.getBillingAddress(); + if (billingAddress != null) { + billingAddress.getCity(); + } + Address shippingAddress = customer.getShippingAddress(); + if (shippingAddress != null) { + shippingAddress.getCity(); + } + List details = order.getDetails(); + for (OrderDetail orderDetail : details) { + orderDetail.getUnitPrice(); + orderDetail.getProduct().getName(); + } + + } + + } + + @Test + public void testFindByIds() { + + ResetBasicData.reset(); + + List ids = Ebean.find(Order.class).findIds(); + Assert.assertTrue(!ids.isEmpty()); + + } + +} diff --git a/src/test/java/com/avaje/tests/rawsql/TestRawSqlOrmQuery.java b/src/test/java/com/avaje/tests/rawsql/TestRawSqlOrmQuery.java index 41c152308..f842622e2 100644 --- a/src/test/java/com/avaje/tests/rawsql/TestRawSqlOrmQuery.java +++ b/src/test/java/com/avaje/tests/rawsql/TestRawSqlOrmQuery.java @@ -61,5 +61,10 @@ public class TestRawSqlOrmQuery extends BaseTestCase { System.out.println(page); System.out.println(list); + + for (Customer customer : list) { + customer.getCretime(); + } + } }