diff --git a/pom.xml b/pom.xml index ac9ceda2b..ee2c36b87 100644 --- a/pom.xml +++ b/pom.xml @@ -103,7 +103,7 @@ io.ebean ebean-annotation - 3.5 + 3.6 diff --git a/src/main/java/io/ebean/ProfileLocation.java b/src/main/java/io/ebean/ProfileLocation.java index 548858549..d433f4c3d 100644 --- a/src/main/java/io/ebean/ProfileLocation.java +++ b/src/main/java/io/ebean/ProfileLocation.java @@ -17,17 +17,17 @@ public interface ProfileLocation { } /** - * Create and return a new ProfileLocation with a given lineNumber. + * Create and return a new ProfileLocation with a given lineNumber and label. */ - static ProfileLocation create(int lineNumber) { - return XServiceProvider.profileLocationFactory().create(lineNumber); + static ProfileLocation create(int lineNumber, String label) { + return XServiceProvider.profileLocationFactory().create(lineNumber, label); } /** * Create and return a new ProfileLocation with a given location. */ - static ProfileLocation create(String location) { - return XServiceProvider.profileLocationFactory().create(location); + static ProfileLocation createAt(String location) { + return XServiceProvider.profileLocationFactory().createAt(location); } /** @@ -40,4 +40,8 @@ public interface ProfileLocation { */ String shortDescription(); + /** + * Add execution time. + */ + void add(long executionTime); } diff --git a/src/main/java/io/ebean/Transaction.java b/src/main/java/io/ebean/Transaction.java index 7df15e90e..743fcc138 100644 --- a/src/main/java/io/ebean/Transaction.java +++ b/src/main/java/io/ebean/Transaction.java @@ -59,6 +59,14 @@ public interface Transaction extends AutoCloseable { */ void register(TransactionCallback callback); + /** + * Set a label on the transaction. + *

+ * This label is used to group transaction execution times for performance metrics reporting. + *

+ */ + void setLabel(String label); + /** * Return true if this transaction is read only. */ diff --git a/src/main/java/io/ebean/meta/MetaInfoManager.java b/src/main/java/io/ebean/meta/MetaInfoManager.java index d38b8e0c2..d9113d156 100644 --- a/src/main/java/io/ebean/meta/MetaInfoManager.java +++ b/src/main/java/io/ebean/meta/MetaInfoManager.java @@ -7,6 +7,11 @@ import java.util.List; */ public interface MetaInfoManager { + /** + * Collect and return the transaction execution metrics. + */ + List collectTransactionStatistics(boolean reset); + /** * Collect and return the non-empty query plan statistics for all the beans. *

diff --git a/src/main/java/io/ebean/meta/MetaTimedMetric.java b/src/main/java/io/ebean/meta/MetaTimedMetric.java new file mode 100644 index 000000000..719ff07fa --- /dev/null +++ b/src/main/java/io/ebean/meta/MetaTimedMetric.java @@ -0,0 +1,43 @@ +package io.ebean.meta; + + +/** + * Timed execution statistics. + */ +public interface MetaTimedMetric { + + /** + * Return the metric name. + */ + String getName(); + + /** + * Return the metric location if defined. + */ + String getLocation(); + + /** + * Return the time the counters started from. + */ + long getStartTime(); + + /** + * Return the total count. + */ + long getCount(); + + /** + * Return the total execution time. + */ + long getTotal(); + + /** + * Return the max execution time. + */ + long getMax(); + + /** + * Return the mean execution time. + */ + long getMean(); +} diff --git a/src/main/java/io/ebean/service/SpiProfileLocationFactory.java b/src/main/java/io/ebean/service/SpiProfileLocationFactory.java index 79d9b8f5a..e5626a69e 100644 --- a/src/main/java/io/ebean/service/SpiProfileLocationFactory.java +++ b/src/main/java/io/ebean/service/SpiProfileLocationFactory.java @@ -15,10 +15,10 @@ public interface SpiProfileLocationFactory { /** * Create a profile location with a line number. */ - ProfileLocation create(int lineNumber); + ProfileLocation create(int lineNumber, String label); /** * Create a known location. */ - ProfileLocation create(String location); + ProfileLocation createAt(String location); } diff --git a/src/main/java/io/ebeaninternal/api/SpiTransaction.java b/src/main/java/io/ebeaninternal/api/SpiTransaction.java index 64d261f88..a8988662f 100644 --- a/src/main/java/io/ebeaninternal/api/SpiTransaction.java +++ b/src/main/java/io/ebeaninternal/api/SpiTransaction.java @@ -25,6 +25,11 @@ import java.sql.SQLException; */ public interface SpiTransaction extends Transaction { + /** + * Return the user defined label for the transaction. + */ + String getLabel(); + /** * Return the string prefix with the transaction id and label used in logging. */ diff --git a/src/main/java/io/ebeaninternal/api/SpiTransactionProxy.java b/src/main/java/io/ebeaninternal/api/SpiTransactionProxy.java index 5e0f7d415..1743a1b7b 100644 --- a/src/main/java/io/ebeaninternal/api/SpiTransactionProxy.java +++ b/src/main/java/io/ebeaninternal/api/SpiTransactionProxy.java @@ -30,6 +30,16 @@ abstract class SpiTransactionProxy implements SpiTransaction { return transaction.translate(message, cause); } + @Override + public void setLabel(String label) { + transaction.setLabel(label); + } + + @Override + public String getLabel() { + return transaction.getLabel(); + } + @Override public void commitAndContinue() { transaction.commitAndContinue(); diff --git a/src/main/java/io/ebeaninternal/metric/MetricFactory.java b/src/main/java/io/ebeaninternal/metric/MetricFactory.java new file mode 100644 index 000000000..3ea15470e --- /dev/null +++ b/src/main/java/io/ebeaninternal/metric/MetricFactory.java @@ -0,0 +1,25 @@ +package io.ebeaninternal.metric; + +/** + * Factory to create timed metric counters. + */ +public interface MetricFactory { + + /** + * Return the factory instance. + */ + static MetricFactory get() { + return MetricServiceProvider.get(); + } + + /** + * Create a timed metric group. + */ + TimedMetricMap createTimedMetricMap(String name); + + /** + * Create a Timed metric. + */ + TimedMetric createTimedMetric(String name); + +} diff --git a/src/main/java/io/ebeaninternal/metric/MetricServiceProvider.java b/src/main/java/io/ebeaninternal/metric/MetricServiceProvider.java new file mode 100644 index 000000000..e90649780 --- /dev/null +++ b/src/main/java/io/ebeaninternal/metric/MetricServiceProvider.java @@ -0,0 +1,31 @@ +package io.ebeaninternal.metric; + +import io.ebeaninternal.server.profile.DMetricFactory; + +import java.util.Iterator; +import java.util.ServiceLoader; + +/** + * Lookup MetricFactory service. + */ +class MetricServiceProvider { + + private static MetricFactory metricFactory = init(); + + private static MetricFactory init() { + + Iterator loader = ServiceLoader.load(MetricFactory.class).iterator(); + if (loader.hasNext()) { + return loader.next(); + } + return new DMetricFactory(); + } + + /** + * Return the MetricFactory implementation. + */ + static MetricFactory get() { + return metricFactory; + } + +} diff --git a/src/main/java/io/ebeaninternal/metric/TimedMetric.java b/src/main/java/io/ebeaninternal/metric/TimedMetric.java new file mode 100644 index 000000000..c45fa19dc --- /dev/null +++ b/src/main/java/io/ebeaninternal/metric/TimedMetric.java @@ -0,0 +1,31 @@ +package io.ebeaninternal.metric; + +import io.ebean.meta.MetaTimedMetric; + +import java.util.List; + +/** + * Metric for timed events like transaction execution times. + */ +public interface TimedMetric { + + /** + * Add a time event (usually in microseconds). + */ + void add(long value); + + /** + * Return true if there are no metrics collected since the last collection. + */ + boolean isEmpty(); + + /** + * Collect the timed metric statistics. + */ + TimedMetricStats collect(boolean reset); + + /** + * Add non empty metrics to the result. + */ + void collect(boolean reset, List result); +} diff --git a/src/main/java/io/ebeaninternal/metric/TimedMetricMap.java b/src/main/java/io/ebeaninternal/metric/TimedMetricMap.java new file mode 100644 index 000000000..3976b5121 --- /dev/null +++ b/src/main/java/io/ebeaninternal/metric/TimedMetricMap.java @@ -0,0 +1,21 @@ +package io.ebeaninternal.metric; + +import io.ebean.meta.MetaTimedMetric; + +import java.util.List; + +/** + * A map of timed metrics keyed by a string. + */ +public interface TimedMetricMap { + + /** + * Add an execution for the given key. + */ + void add(String key, long exeMicros); + + /** + * Add non empty metrics to the given result. + */ + void collect(boolean reset, List result); +} diff --git a/src/main/java/io/ebeaninternal/metric/TimedMetricStats.java b/src/main/java/io/ebeaninternal/metric/TimedMetricStats.java new file mode 100644 index 000000000..0353e56ab --- /dev/null +++ b/src/main/java/io/ebeaninternal/metric/TimedMetricStats.java @@ -0,0 +1,14 @@ +package io.ebeaninternal.metric; + +import io.ebean.meta.MetaTimedMetric; + +/** + * Extend public MetaTimedMetric with ability to set details from profile location. + */ +public interface TimedMetricStats extends MetaTimedMetric { + + /** + * Additionally set the location. + */ + void setLocation(String location); +} diff --git a/src/main/java/io/ebeaninternal/server/core/DefaultMetaInfoManager.java b/src/main/java/io/ebeaninternal/server/core/DefaultMetaInfoManager.java index ee1f7a3e0..f69aea9d2 100644 --- a/src/main/java/io/ebeaninternal/server/core/DefaultMetaInfoManager.java +++ b/src/main/java/io/ebeaninternal/server/core/DefaultMetaInfoManager.java @@ -3,6 +3,7 @@ package io.ebeaninternal.server.core; import io.ebean.meta.MetaInfoManager; import io.ebean.meta.MetaObjectGraphNodeStats; import io.ebean.meta.MetaQueryPlanStatistic; +import io.ebean.meta.MetaTimedMetric; import io.ebeaninternal.server.deploy.BeanDescriptor; import io.ebeaninternal.server.query.CQueryPlanStatsCollector; @@ -20,6 +21,11 @@ public class DefaultMetaInfoManager implements MetaInfoManager { this.server = server; } + @Override + public List collectTransactionStatistics(boolean reset) { + return server.collectTransactionStatistics(reset); + } + @Override public List collectQueryPlanStatistics(boolean reset) { diff --git a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java index 154c847a8..13558b0d6 100644 --- a/src/main/java/io/ebeaninternal/server/core/DefaultServer.java +++ b/src/main/java/io/ebeaninternal/server/core/DefaultServer.java @@ -47,6 +47,7 @@ import io.ebean.event.BeanPersistController; import io.ebean.event.readaudit.ReadAuditLogger; import io.ebean.event.readaudit.ReadAuditPrepare; import io.ebean.meta.MetaInfoManager; +import io.ebean.meta.MetaTimedMetric; import io.ebean.plugin.BeanType; import io.ebean.plugin.Plugin; import io.ebean.plugin.SpiServer; @@ -2214,4 +2215,8 @@ public final class DefaultServer implements SpiServer, SpiEbeanServer { } } } + + public List collectTransactionStatistics(boolean reset) { + return transactionManager.collectTransactionStatistics(reset); + } } diff --git a/src/main/java/io/ebeaninternal/server/core/NoTransaction.java b/src/main/java/io/ebeaninternal/server/core/NoTransaction.java index 5b826035b..97c480dbf 100644 --- a/src/main/java/io/ebeaninternal/server/core/NoTransaction.java +++ b/src/main/java/io/ebeaninternal/server/core/NoTransaction.java @@ -25,6 +25,16 @@ class NoTransaction implements SpiTransaction { static final NoTransaction INSTANCE = new NoTransaction(); + @Override + public void setLabel(String label) { + // do nothing + } + + @Override + public String getLabel() { + return null; + } + @Override public boolean isActive() { // always false diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java index f911712ed..3a225cc92 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java @@ -416,8 +416,8 @@ public class BeanDescriptor implements BeanType { this.name = InternString.intern(deploy.getName()); this.baseTableAlias = "t0"; this.fullName = InternString.intern(deploy.getFullName()); - this.locationById = ProfileLocation.create(fullName+".byId"); - this.locationAll = ProfileLocation.create(fullName+".all"); + this.locationById = ProfileLocation.createAt(fullName+".byId"); + this.locationAll = ProfileLocation.createAt(fullName+".all"); this.profileBeanId = deploy.getProfileId(); this.beanType = deploy.getBeanType(); this.rootBeanType = PersistenceContextUtil.root(beanType); diff --git a/src/main/java/io/ebeaninternal/server/profile/BasicProfileLocation.java b/src/main/java/io/ebeaninternal/server/profile/BasicProfileLocation.java index 94ef41106..4f0a9071b 100644 --- a/src/main/java/io/ebeaninternal/server/profile/BasicProfileLocation.java +++ b/src/main/java/io/ebeaninternal/server/profile/BasicProfileLocation.java @@ -19,6 +19,11 @@ class BasicProfileLocation implements ProfileLocation { return shortDescription; } + @Override + public void add(long executionTime) { + // do nothing + } + public String obtain() { return location; } diff --git a/src/main/java/io/ebeaninternal/server/profile/DMetricFactory.java b/src/main/java/io/ebeaninternal/server/profile/DMetricFactory.java new file mode 100644 index 000000000..c2f127d0a --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/DMetricFactory.java @@ -0,0 +1,21 @@ +package io.ebeaninternal.server.profile; + +import io.ebeaninternal.metric.MetricFactory; +import io.ebeaninternal.metric.TimedMetric; +import io.ebeaninternal.metric.TimedMetricMap; + +/** + * Default metric factory implementation. + */ +public class DMetricFactory implements MetricFactory { + + @Override + public TimedMetricMap createTimedMetricMap(String name) { + return new DTimedMetricMap(name); + } + + @Override + public TimedMetric createTimedMetric(String name) { + return new DTimedMetric(name); + } +} diff --git a/src/main/java/io/ebeaninternal/server/profile/DProfileLocation.java b/src/main/java/io/ebeaninternal/server/profile/DProfileLocation.java index 0ab43d9f1..2ac6f09f2 100644 --- a/src/main/java/io/ebeaninternal/server/profile/DProfileLocation.java +++ b/src/main/java/io/ebeaninternal/server/profile/DProfileLocation.java @@ -18,9 +18,12 @@ class DProfileLocation implements ProfileLocation { private final int lineNumber; DProfileLocation() { - this.lineNumber = 0; + this(0); } + /** + * Create with a given line number. + */ DProfileLocation(int lineNumber) { this.lineNumber = lineNumber; } @@ -29,6 +32,11 @@ class DProfileLocation implements ProfileLocation { return "location: " + location; } + @Override + public void add(long executionTime) { + // do nothing + } + public String obtain() { // atomic assignment so happy with this if (location == null) { diff --git a/src/main/java/io/ebeaninternal/server/profile/DProfileLocationFactory.java b/src/main/java/io/ebeaninternal/server/profile/DProfileLocationFactory.java index 8d4e592d0..241c2a0ac 100644 --- a/src/main/java/io/ebeaninternal/server/profile/DProfileLocationFactory.java +++ b/src/main/java/io/ebeaninternal/server/profile/DProfileLocationFactory.java @@ -2,6 +2,8 @@ package io.ebeaninternal.server.profile; import io.ebean.ProfileLocation; import io.ebean.service.SpiProfileLocationFactory; +import io.ebeaninternal.metric.MetricFactory; +import io.ebeaninternal.metric.TimedMetric; /** * Default implementation of the profile location factory. @@ -14,12 +16,17 @@ public class DProfileLocationFactory implements SpiProfileLocationFactory { } @Override - public ProfileLocation create(int lineNumber) { - return new DProfileLocation(lineNumber); + public ProfileLocation create(int lineNumber, String label) { + + TimedMetric timedMetric = MetricFactory.get().createTimedMetric("txn.named." + label); + + DTimedProfileLocation loc = new DTimedProfileLocation(lineNumber, label, timedMetric); + TimedProfileLocationRegistry.register(loc); + return loc; } @Override - public ProfileLocation create(String location) { + public ProfileLocation createAt(String location) { return new BasicProfileLocation(location); } } diff --git a/src/main/java/io/ebeaninternal/server/profile/DTimeMetricStats.java b/src/main/java/io/ebeaninternal/server/profile/DTimeMetricStats.java new file mode 100644 index 000000000..c69d1c00b --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/DTimeMetricStats.java @@ -0,0 +1,100 @@ +package io.ebeaninternal.server.profile; + +import io.ebeaninternal.metric.TimedMetricStats; + +/** + * Snapshot of the current statistics for a Counter or TimeCounter. + */ +class DTimeMetricStats implements TimedMetricStats { + + private final String name; + + private String location; + + private final long startTime; + + private final long count; + + private final long total; + + private final long max; + + DTimeMetricStats(String name, long collectionStart, long count, long total, long max) { + this.name = name; + this.startTime = collectionStart; + this.count = count; + this.total = total; + // collection is racy so sanitize the max value if it has not been set + // this most likely would happen when count = 1 so max = mean + this.max = max != Long.MIN_VALUE ? max : (count < 1 ? 0 : Math.round(total / count)); + } + + public String toString() { + StringBuilder sb = new StringBuilder(); + if (location != null) { + sb.append("loc:").append(location).append(" "); + } + if (name != null) { + sb.append("name:").append(name).append(" "); + } + sb.append("count:").append(count) + .append(" total:").append(total) + .append(" max:").append(max); + return sb.toString(); + } + + public void setLocation(String location) { + this.location = location; + } + + @Override + public String getName() { + return name; + } + + @Override + public String getLocation() { + return location; + } + + /** + * Return the time the counter started statistics collection. + */ + @Override + public long getStartTime() { + return startTime; + } + + /** + * Return the count of values collected. + */ + @Override + public long getCount() { + return count; + } + + /** + * Return the total of all the values. + */ + @Override + public long getTotal() { + return total; + } + + /** + * Return the Max value collected. + */ + @Override + public long getMax() { + return max; + } + + /** + * Return the mean value rounded up. + */ + @Override + public long getMean() { + return (count < 1) ? 0L : Math.round((double)(total / count)); + } + +} diff --git a/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java b/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java new file mode 100644 index 000000000..be7927c29 --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java @@ -0,0 +1,127 @@ +package io.ebeaninternal.server.profile; + +import io.ebean.meta.MetaTimedMetric; +import io.ebeaninternal.metric.TimedMetric; + +import java.util.List; +import java.util.concurrent.atomic.AtomicLong; +import java.util.concurrent.atomic.LongAccumulator; +import java.util.concurrent.atomic.LongAdder; + +/** + * Used to collect timed execution statistics. + *

+ * It is intended for high concurrent updates to the statistics and relatively infrequent reads. + *

+ */ +class DTimedMetric implements TimedMetric { + + protected final String name; + + protected final LongAdder count = new LongAdder(); + + protected final LongAdder total = new LongAdder(); + + protected final LongAccumulator max = new LongAccumulator(Math::max, Long.MIN_VALUE); + + protected final AtomicLong startTime = new AtomicLong(System.currentTimeMillis()); + + DTimedMetric(String name) { + this.name = name; + } + + /** + * Add a value. Usually the value is Time or Bytes etc. + */ + @Override + public void add(long value) { + + count.increment(); + total.add(value); + max.accumulate(value); + } + + @Override + public boolean isEmpty() { + return count.sum() == 0; + } + + @Override + public void collect(boolean reset, List result) { + DTimeMetricStats metric = collect(reset); + if (metric != null) { + result.add(metric); + } + } + +// @Override + public DTimeMetricStats collect(boolean reset) { + boolean empty = count.sum() == 0; + if (empty) { + if (reset) { + startTime.set(System.currentTimeMillis()); + } + return null; + } else { + return getStatistics(reset); + } + } + + /** + * Return the current statistics resetting the internal values if reset is true. + */ + public DTimeMetricStats getStatistics(boolean reset) { + + if (reset) { + // Note these values are not guaranteed to be consistent wrt each other + // but should be reasonably consistent (small time between count and total) + final long maxVal = max.getThenReset(); + final long totalVal = total.sumThenReset(); + final long countVal = count.sumThenReset(); + final long startTimeVal = startTime.getAndSet(System.currentTimeMillis()); + return new DTimeMetricStats(name, startTimeVal, countVal, totalVal, maxVal); + + } else { + return new DTimeMetricStats(name, startTime.get(), count.sum(), total.sum(), max.get()); + } + } + + /** + * Reset all the internal counters and start time. + */ + public void reset() { + startTime.set(System.currentTimeMillis()); + max.reset(); + count.reset(); + total.reset(); + } + + /** + * Return the start time. + */ + public long getStartTime() { + return startTime.get(); + } + + /** + * Return the count of values. + */ + public long getCount() { + return count.sum(); + } + + /** + * Return the total of values. + */ + public long getTotal() { + return total.sum(); + } + + /** + * Return the max value. + */ + public long getMax() { + return max.get(); + } + +} diff --git a/src/main/java/io/ebeaninternal/server/profile/DTimedMetricMap.java b/src/main/java/io/ebeaninternal/server/profile/DTimedMetricMap.java new file mode 100644 index 000000000..d077e7aea --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/DTimedMetricMap.java @@ -0,0 +1,30 @@ +package io.ebeaninternal.server.profile; + +import io.ebean.meta.MetaTimedMetric; +import io.ebeaninternal.metric.TimedMetricMap; + +import java.util.List; +import java.util.concurrent.ConcurrentHashMap; + +class DTimedMetricMap implements TimedMetricMap { + + private final String name; + + private final ConcurrentHashMap map = new ConcurrentHashMap<>(); + + DTimedMetricMap(String name) { + this.name = name; + } + + @Override + public void add(String key, long exeMicros) { + map.computeIfAbsent(key, (k)-> new DTimedMetric(name + key)).add(exeMicros); + } + + @Override + public void collect(boolean reset, List list) { + for (DTimedMetric value : map.values()) { + value.collect(reset, list); + } + } +} diff --git a/src/main/java/io/ebeaninternal/server/profile/DTimedProfileLocation.java b/src/main/java/io/ebeaninternal/server/profile/DTimedProfileLocation.java new file mode 100644 index 000000000..ea62a335b --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/DTimedProfileLocation.java @@ -0,0 +1,49 @@ +package io.ebeaninternal.server.profile; + +import io.ebean.meta.MetaTimedMetric; +import io.ebeaninternal.metric.TimedMetric; +import io.ebeaninternal.metric.TimedMetricStats; + +import java.util.List; + +/** + * Default profile location that uses stack trace. + */ +class DTimedProfileLocation extends DProfileLocation implements TimedProfileLocation { + + private final String label; + + private final TimedMetric timedMetric; + + DTimedProfileLocation(int lineNumber, String label, TimedMetric timedMetric) { + super(lineNumber); + this.label = label; + this.timedMetric = timedMetric; + } + + @Override + public String getLabel() { + return label; + } + + @Override + public TimedMetric getMetric() { + return timedMetric; + } + + @Override + public void add(long executionTime) { + timedMetric.add(executionTime); + } + + @Override + public void collect(boolean reset, List list) { + + TimedMetricStats collect = timedMetric.collect(reset); + if (collect != null) { + collect.setLocation(obtain()); + list.add(collect); + } + } + +} diff --git a/src/main/java/io/ebeaninternal/server/profile/TimedProfileLocation.java b/src/main/java/io/ebeaninternal/server/profile/TimedProfileLocation.java new file mode 100644 index 000000000..36f702ecd --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/TimedProfileLocation.java @@ -0,0 +1,28 @@ +package io.ebeaninternal.server.profile; + +import io.ebean.ProfileLocation; +import io.ebean.meta.MetaTimedMetric; +import io.ebeaninternal.metric.TimedMetric; + +import java.util.List; + +/** + * ProfileLocation that collects timing metrics. + */ +public interface TimedProfileLocation extends ProfileLocation { + + /** + * Return the label. + */ + String getLabel(); + + /** + * Return the metric. + */ + TimedMetric getMetric(); + + /** + * Collect the metrics adding to the given list if the metrics are non empty. + */ + void collect(boolean reset, List list); +} diff --git a/src/main/java/io/ebeaninternal/server/profile/TimedProfileLocationRegistry.java b/src/main/java/io/ebeaninternal/server/profile/TimedProfileLocationRegistry.java new file mode 100644 index 000000000..018130b2d --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/profile/TimedProfileLocationRegistry.java @@ -0,0 +1,27 @@ +package io.ebeaninternal.server.profile; + +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; + +/** + * Global registry of the TimedProfileLocation instances created. + */ +public class TimedProfileLocationRegistry { + + private static final List list = Collections.synchronizedList(new ArrayList()); + + /** + * Register the timed profile location instance. + */ + public static void register(TimedProfileLocation location) { + list.add(location); + } + + /** + * Return all the registered timed locations. + */ + public static List registered() { + return list; + } +} diff --git a/src/main/java/io/ebeaninternal/server/transaction/ImplicitReadOnlyTransaction.java b/src/main/java/io/ebeaninternal/server/transaction/ImplicitReadOnlyTransaction.java index 3699eb575..526437a7a 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/ImplicitReadOnlyTransaction.java +++ b/src/main/java/io/ebeaninternal/server/transaction/ImplicitReadOnlyTransaction.java @@ -41,6 +41,8 @@ class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEventCode private static final String notExpectedMessage = "Not expected on read only transaction"; + private final TransactionManager manager; + /** * The status of the transaction. */ @@ -61,23 +63,37 @@ class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEventCode private Map userObjects; + private long startNanos; + /** * Create without a tenantId. */ - ImplicitReadOnlyTransaction(Connection connection) { + ImplicitReadOnlyTransaction(TransactionManager manager, Connection connection) { + this.manager = manager; this.active = true; this.connection = connection; this.persistenceContext = new DefaultPersistenceContext(); + this.startNanos = System.nanoTime(); } /** * Create with a tenantId. */ - ImplicitReadOnlyTransaction(Connection connection, Object tenantId) { - this(connection); + ImplicitReadOnlyTransaction(TransactionManager manager, Connection connection, Object tenantId) { + this(manager, connection); this.tenantId = tenantId; } + @Override + public void setLabel(String label) { + // do nothing + } + + @Override + public String getLabel() { + return null; + } + @Override public long profileOffset() { return 0; @@ -475,6 +491,8 @@ class ImplicitReadOnlyTransaction implements SpiTransaction, TxnProfileEventCode } connection = null; active = false; + long exeMicros = (System.nanoTime() - startNanos) / 1000L; + manager.collectMetricReadOnly(exeMicros); } /** diff --git a/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java b/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java index f9b4034bb..75055fb48 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java +++ b/src/main/java/io/ebeaninternal/server/transaction/JdbcTransaction.java @@ -55,6 +55,11 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes { */ protected final String id; + /** + * The user defined label to group execution statistics. + */ + protected String label; + /** * Flag to indicate if this was an explicitly created Transaction. */ @@ -176,6 +181,8 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes { protected ProfileLocation profileLocation; + protected final long startNanos; + /** * Create without ProfileStream option (no profiling). */ @@ -196,6 +203,7 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes { this.manager = manager; this.connection = connection; this.persistenceContext = new DefaultPersistenceContext(); + this.startNanos = System.nanoTime(); if (manager == null) { this.skipCacheAfterWrite = true; @@ -216,6 +224,16 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes { } } + @Override + public void setLabel(String label) { + this.label = label; + } + + @Override + public String getLabel() { + return label; + } + @Override public long profileOffset() { return (profileStream == null) ? 0 : profileStream.offset(); @@ -980,8 +998,17 @@ public class JdbcTransaction implements SpiTransaction, TxnProfileEventCodes { } private void profileEnd() { - if (profileStream != null) { - profileStream.end(manager); + if (manager != null) { + long exeMicros = (System.nanoTime() - startNanos) / 1000L; + if (profileLocation != null) { + profileLocation.add(exeMicros); + } else if (label != null) { + manager.collectMetricNamed(exeMicros, label); + } + manager.collectMetric(exeMicros); + if (profileStream != null) { + profileStream.end(manager); + } } } diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasicWithRead.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasicWithRead.java index 920fd05de..57048bc28 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasicWithRead.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryBasicWithRead.java @@ -32,7 +32,7 @@ class TransactionFactoryBasicWithRead extends TransactionFactoryBasic { Connection connection = null; try { connection = readOnlyDataSource.getConnection(); - return new ImplicitReadOnlyTransaction(connection); + return new ImplicitReadOnlyTransaction(manager, connection); } catch (PersistenceException ex) { JdbcClose.close(connection); diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenantWithRead.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenantWithRead.java index 15b26ca34..94f83d5fd 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenantWithRead.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionFactoryTenantWithRead.java @@ -32,7 +32,7 @@ class TransactionFactoryTenantWithRead extends TransactionFactoryTenant { tenantId = tenantProvider.currentId(); } connection = dataSourceSupplier.getReadOnlyConnection(tenantId); - return new ImplicitReadOnlyTransaction(connection, tenantId); + return new ImplicitReadOnlyTransaction(manager, connection, tenantId); } catch (PersistenceException ex) { JdbcClose.close(connection); diff --git a/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java b/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java index 126820fef..d098356a5 100644 --- a/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java +++ b/src/main/java/io/ebeaninternal/server/transaction/TransactionManager.java @@ -8,13 +8,19 @@ import io.ebean.config.dbplatform.DatabasePlatform.OnQueryOnly; import io.ebean.event.changelog.ChangeLogListener; import io.ebean.event.changelog.ChangeLogPrepare; import io.ebean.event.changelog.ChangeSet; +import io.ebean.meta.MetaTimedMetric; import io.ebeaninternal.api.SpiProfileHandler; import io.ebeaninternal.api.SpiTransaction; import io.ebeaninternal.api.TransactionEvent; import io.ebeaninternal.api.TransactionEventTable; import io.ebeaninternal.api.TransactionEventTable.TableIUD; +import io.ebeaninternal.metric.MetricFactory; +import io.ebeaninternal.metric.TimedMetric; +import io.ebeaninternal.metric.TimedMetricMap; import io.ebeaninternal.server.cluster.ClusterManager; import io.ebeaninternal.server.deploy.BeanDescriptorManager; +import io.ebeaninternal.server.profile.TimedProfileLocation; +import io.ebeaninternal.server.profile.TimedProfileLocationRegistry; import io.ebeanservice.docstore.api.DocStoreTransaction; import io.ebeanservice.docstore.api.DocStoreUpdateProcessor; import io.ebeanservice.docstore.api.DocStoreUpdates; @@ -25,6 +31,7 @@ import javax.persistence.PersistenceException; import javax.sql.DataSource; import java.sql.Connection; import java.sql.SQLException; +import java.util.ArrayList; import java.util.List; import java.util.Set; @@ -113,6 +120,11 @@ public class TransactionManager { private final SpiProfileHandler profileHandler; + private final MetricFactory metricFactory; + private final TimedMetric txnMain; + private final TimedMetric txnReadOnly; + private final TimedMetricMap txnNamed; + /** * Create the TransactionManager */ @@ -142,6 +154,10 @@ public class TransactionManager { CurrentTenantProvider tenantProvider = options.config.getCurrentTenantProvider(); this.transactionFactory = TransactionFactoryBuilder.build(this, dataSourceSupplier, tenantProvider); + this.metricFactory = MetricFactory.get(); + this.txnMain = metricFactory.createTimedMetric("txn.main"); + this.txnReadOnly = metricFactory.createTimedMetric("txn.readonly"); + this.txnNamed = metricFactory.createTimedMetricMap("txn.named."); } /** @@ -266,7 +282,7 @@ public class TransactionManager { protected SpiTransaction createTransaction(int profileId, boolean explicit, Connection c, long id) { ProfileStream profileStream = profileHandler.createProfileStream(profileId); - return new JdbcTransaction(profileStream,prefix + id, explicit, c, this); + return new JdbcTransaction(profileStream, prefix + id, explicit, c, this); } /** @@ -424,4 +440,42 @@ public class TransactionManager { public void profileCollect(TransactionProfile transactionProfile) { profileHandler.collectTransactionProfile(transactionProfile); } + + /** + * Collect execution time for an explicit transaction. + */ + public void collectMetric(long exeMicros) { + txnMain.add(exeMicros); + } + + /** + * Collect execution time for implicit read only transaction. + */ + public void collectMetricReadOnly(long exeMicros) { + txnReadOnly.add(exeMicros); + } + + /** + * Collect execution time for a named transaction. + */ + public void collectMetricNamed(long exeMicros, String label) { + txnNamed.add(label, exeMicros); + } + + /** + * Collect the transaction execution statistics since the last reset. + */ + public List collectTransactionStatistics(boolean reset) { + + List list = new ArrayList<>(); + + txnMain.collect(reset, list); + txnReadOnly.collect(reset, list); + for (TimedProfileLocation timedLocation : TimedProfileLocationRegistry.registered()) { + timedLocation.collect(reset, list); + } + txnNamed.collect(reset, list); + + return list; + } } diff --git a/src/test/java/io/ebeaninternal/server/profile/BasicProfileLocationTest.java b/src/test/java/io/ebeaninternal/server/profile/BasicProfileLocationTest.java index 6a23e4bae..a6295b842 100644 --- a/src/test/java/io/ebeaninternal/server/profile/BasicProfileLocationTest.java +++ b/src/test/java/io/ebeaninternal/server/profile/BasicProfileLocationTest.java @@ -1,5 +1,6 @@ package io.ebeaninternal.server.profile; +import io.ebeaninternal.metric.MetricFactory; import org.junit.Test; import static org.assertj.core.api.Assertions.assertThat; @@ -9,7 +10,7 @@ public class BasicProfileLocationTest { @Test public void obtain() { - DProfileLocation loc = new DProfileLocation(12); + DProfileLocation loc = new DTimedProfileLocation(12, "foo", MetricFactory.get().createTimedMetric("junk")); assertThat(loc.obtain()).endsWith(":12)"); assertThat(loc.shortDescription()).isEqualTo("NativeMethodAccessorImpl.invoke0(Native Method:12)"); diff --git a/src/test/java/org/tests/batchinsert/TestBatchInsertFlush.java b/src/test/java/org/tests/batchinsert/TestBatchInsertFlush.java index 31bbbdb8d..96437d38b 100644 --- a/src/test/java/org/tests/batchinsert/TestBatchInsertFlush.java +++ b/src/test/java/org/tests/batchinsert/TestBatchInsertFlush.java @@ -4,12 +4,15 @@ import io.ebean.BaseTestCase; import io.ebean.Ebean; import io.ebean.EbeanServer; import io.ebean.Transaction; -import io.ebean.annotation.Transactional; import io.ebean.annotation.PersistBatch; +import io.ebean.annotation.Transactional; +import io.ebean.meta.MetaInfoManager; +import io.ebean.meta.MetaTimedMetric; +import io.ebeaninternal.api.SpiTransaction; import org.ebeantest.LoggedSqlCollector; +import org.junit.Test; import org.tests.model.basic.Customer; import org.tests.model.basic.EBasicVer; -import org.junit.Test; import org.tests.model.basic.TSDetail; import org.tests.model.basic.TSMaster; @@ -26,11 +29,15 @@ public class TestBatchInsertFlush extends BaseTestCase { EbeanServer server = Ebean.getDefaultServer(); + MetaInfoManager metaInfoManager = server.getMetaInfoManager(); + metaInfoManager.collectTransactionStatistics(true); + Transaction transaction = server.beginTransaction(); try { transaction.setPersistCascade(false); transaction.setBatchSize(10); transaction.setBatch(PersistBatch.ALL); + transaction.setLabel("TestBatchInsertFlush.no_cascade"); LoggedSqlCollector.start(); @@ -64,11 +71,19 @@ public class TestBatchInsertFlush extends BaseTestCase { // detail assertThat(sql.get(2)).contains("insert into t_detail_with_other_namexxxyy"); + assertThat(((SpiTransaction)transaction).getLabel()).isEqualTo("TestBatchInsertFlush.no_cascade"); } finally { transaction.end(); } + List txnStats = metaInfoManager.collectTransactionStatistics(true); + assertThat(txnStats).hasSize(1); + assertThat(txnStats.get(0).getName()).isEqualTo("txn.named.TestBatchInsertFlush.no_cascade"); + + for (MetaTimedMetric txnMetric : txnStats) { + System.out.println(txnMetric); + } } @Test diff --git a/src/test/java/org/tests/profile/ProfileLocationTest.java b/src/test/java/org/tests/profile/ProfileLocationTest.java index 49499f8b5..ef30d3bfa 100644 --- a/src/test/java/org/tests/profile/ProfileLocationTest.java +++ b/src/test/java/org/tests/profile/ProfileLocationTest.java @@ -7,15 +7,20 @@ import static org.assertj.core.api.Assertions.assertThat; public class ProfileLocationTest { - private static ProfileLocation loc = ProfileLocation.create(12); - - @Test - public void test() { - - assertThat(doIt()).isEqualTo("org.tests.profile.ProfileLocationTest.doIt(ProfileLocationTest.java:19)"); - } + private static ProfileLocation loc = ProfileLocation.create(12, "foo"); private String doIt() { return loc.obtain(); } + + @Test + public void test_obtain() { + + assertThat(doIt()).isEqualTo("org.tests.profile.ProfileLocationTest.doIt(ProfileLocationTest.java:13)"); + } + + @Test + public void test_add() { + loc.add(100); + } } diff --git a/src/test/java/org/tests/query/finder/TestCustomerFinder.java b/src/test/java/org/tests/query/finder/TestCustomerFinder.java index 65cae26a9..554c6c9a1 100644 --- a/src/test/java/org/tests/query/finder/TestCustomerFinder.java +++ b/src/test/java/org/tests/query/finder/TestCustomerFinder.java @@ -5,6 +5,7 @@ import io.ebean.Ebean; import io.ebean.Transaction; import io.ebean.meta.MetaInfoManager; import io.ebean.meta.MetaQueryPlanStatistic; +import io.ebean.meta.MetaTimedMetric; import org.ebeantest.LoggedSqlCollector; import org.junit.Test; import org.tests.model.basic.Customer; @@ -137,6 +138,7 @@ public class TestCustomerFinder extends BaseTestCase { MetaInfoManager metaInfoManager = Ebean.getDefaultServer().getMetaInfoManager(); metaInfoManager.collectQueryPlanStatistics(true); + metaInfoManager.collectTransactionStatistics(true); List customers = Customer.find.all(); assertThat(customers).isNotEmpty(); @@ -157,6 +159,10 @@ public class TestCustomerFinder extends BaseTestCase { for (MetaQueryPlanStatistic planStat : planStats) { System.out.println(planStat); } + + for (MetaTimedMetric txnTimed : metaInfoManager.collectTransactionStatistics(true)) { + System.out.println(txnTimed); + } } } diff --git a/src/test/resources/ebean.mf b/src/test/resources/ebean.mf index c18791604..7bda05850 100644 --- a/src/test/resources/ebean.mf +++ b/src/test/resources/ebean.mf @@ -1,5 +1,5 @@ agent-use-only: true -profile-location: true +profile-location: false entity-packages: org,misc transactional-packages: org querybean-packages: none