diff --git a/src/main/java/io/ebean/meta/MetricType.java b/src/main/java/io/ebean/meta/MetricType.java index e0d718170..0a79bb7f4 100644 --- a/src/main/java/io/ebean/meta/MetricType.java +++ b/src/main/java/io/ebean/meta/MetricType.java @@ -10,6 +10,11 @@ public enum MetricType { */ TXN, + /** + * ORM Insert Update or Delete. + */ + IUD, + /** * ORM queries. */ diff --git a/src/main/java/io/ebean/metric/TimedMetric.java b/src/main/java/io/ebean/metric/TimedMetric.java index fb2589273..cd424a41f 100644 --- a/src/main/java/io/ebean/metric/TimedMetric.java +++ b/src/main/java/io/ebean/metric/TimedMetric.java @@ -17,6 +17,11 @@ public interface TimedMetric { */ void add(long micros, long beans); + /** + * Add a time event for a batch of beans. + */ + void addBatchSince(long startNanos, int batch); + /** * Add a time event given the start nanos. */ diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequest.java b/src/main/java/io/ebeaninternal/server/core/PersistRequest.java index 3b8fe7075..eac7c40d3 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequest.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequest.java @@ -57,6 +57,15 @@ public abstract class PersistRequest extends BeanRequest implements BatchPostExe this.label = label; } + @Override + public void addTimingBatch(long startNanos, int size) { + // nothing by default + } + + public void addTimingNoBatch(long startNanos) { + // nothing by default + } + /** * Effectively set start nanos if we are collecting metrics on a label. */ diff --git a/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java b/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java index 0804a0604..da9b7745b 100644 --- a/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java +++ b/src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java @@ -229,6 +229,16 @@ public final class PersistRequestBean extends PersistRequest implements BeanP initGeneratedProperties(); } + @Override + public void addTimingBatch(long startNanos, int batch) { + beanDescriptor.metricPersistBatch(type, startNanos, batch); + } + + @Override + public void addTimingNoBatch(long startNanos) { + beanDescriptor.metricPersistNoBatch(type, startNanos); + } + /** * Add to profile as batched bean insert, update or delete. */ diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java index f76aa143b..baa4e4caa 100644 --- a/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java @@ -143,6 +143,8 @@ public class BeanDescriptor implements BeanType, STreeType { private boolean batchEscalateOnCascadeInsert; private boolean batchEscalateOnCascadeDelete; + private final BeanIudMetrics iudMetrics; + public enum EntityType { ORM, EMBEDDED, VIEW, SQL, DOC } @@ -441,7 +443,7 @@ public class BeanDescriptor implements BeanType, STreeType { this.beanType = deploy.getBeanType(); this.rootBeanType = PersistenceContextUtil.root(beanType); this.prototypeEntityBean = createPrototypeEntityBean(beanType); - + this.iudMetrics = new BeanIudMetrics(name); this.namedQuery = deploy.getNamedQuery(); this.namedRawSql = deploy.getNamedRawSql(); this.inheritInfo = deploy.getInheritInfo(); @@ -898,6 +900,14 @@ public class BeanDescriptor implements BeanType, STreeType { } } + public void metricPersistBatch(PersistRequest.Type type, long startNanos, int size) { + iudMetrics.addBatch(type, startNanos, size); + } + + public void metricPersistNoBatch(PersistRequest.Type type, long startNanos) { + iudMetrics.addNoBatch(type, startNanos); + } + public void merge(EntityBean bean, EntityBean existing) { EntityBeanIntercept fromEbi = bean._ebean_getIntercept(); @@ -1684,6 +1694,7 @@ public class BeanDescriptor implements BeanType, STreeType { * Visit all the ORM query plan metrics (includes UpdateQuery with updates and deletes). */ public void visitMetrics(MetricVisitor visitor) { + iudMetrics.visit(visitor); for (CQueryPlan queryPlan : queryPlanCache.values()) { if (!queryPlan.isEmptyStats()) { visitor.visitOrmQuery(queryPlan.getSnapshot(visitor.isReset())); diff --git a/src/main/java/io/ebeaninternal/server/deploy/BeanIudMetrics.java b/src/main/java/io/ebeaninternal/server/deploy/BeanIudMetrics.java new file mode 100644 index 000000000..0780c733d --- /dev/null +++ b/src/main/java/io/ebeaninternal/server/deploy/BeanIudMetrics.java @@ -0,0 +1,82 @@ +package io.ebeaninternal.server.deploy; + +import io.ebean.meta.MetricType; +import io.ebean.meta.MetricVisitor; +import io.ebean.metric.MetricFactory; +import io.ebean.metric.TimedMetric; +import io.ebeaninternal.server.core.PersistRequest; + +/** + * Metrics for ORM Insert Update and Delete for a given bean type. + */ +class BeanIudMetrics { + + private final TimedMetric insert; + private final TimedMetric update; + private final TimedMetric delete; + private final TimedMetric insertBatch; + private final TimedMetric updateBatch; + private final TimedMetric deleteBatch; + + /** + * Create for a given bean type. + */ + BeanIudMetrics(String beanShortName) { + + MetricFactory metricFactory = MetricFactory.get(); + String prefix = "iud." + beanShortName; + this.insert = metricFactory.createTimedMetric(MetricType.IUD, prefix + ".insert"); + this.update = metricFactory.createTimedMetric(MetricType.IUD, prefix + ".update"); + this.delete = metricFactory.createTimedMetric(MetricType.IUD, prefix + ".delete"); + this.insertBatch = metricFactory.createTimedMetric(MetricType.IUD, prefix + ".insertBatch"); + this.updateBatch = metricFactory.createTimedMetric(MetricType.IUD, prefix + ".updateBatch"); + this.deleteBatch = metricFactory.createTimedMetric(MetricType.IUD, prefix + ".deleteBatch"); + } + + /** + * Add batch persist metric. + */ + void addBatch(PersistRequest.Type type, long startNanos, int batch) { + switch (type) { + case INSERT: + insertBatch.addBatchSince(startNanos, batch); + break; + case UPDATE: + case DELETE_SOFT: + updateBatch.addBatchSince(startNanos, batch); + break; + case DELETE: + case DELETE_PERMANENT: + deleteBatch.addBatchSince(startNanos, batch); + break; + } + } + + /** + * Add Non-batch persist metric. + */ + void addNoBatch(PersistRequest.Type type, long startNanos) { + switch (type) { + case INSERT: + insert.addSinceNanos(startNanos); + break; + case UPDATE: + case DELETE_SOFT: + update.addSinceNanos(startNanos); + break; + case DELETE: + case DELETE_PERMANENT: + delete.addSinceNanos(startNanos); + break; + } + } + + void visit(MetricVisitor visitor) { + insert.visit(visitor); + update.visit(visitor); + delete.visit(visitor); + insertBatch.visit(visitor); + updateBatch.visit(visitor); + deleteBatch.visit(visitor); + } +} diff --git a/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java b/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java index 38f032e3c..c17be92d1 100644 --- a/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java +++ b/src/main/java/io/ebeaninternal/server/persist/BatchPostExecute.java @@ -40,4 +40,9 @@ public interface BatchPostExecute { * Add as event to the profiling. */ void profile(long offset, int batchSize); + + /** + * Add timing metrics for batch persist. + */ + void addTimingBatch(long startNanos, int batch); } diff --git a/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java b/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java index e1bf8b290..d67c0ad2a 100644 --- a/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java +++ b/src/main/java/io/ebeaninternal/server/persist/BatchedPstmt.java @@ -44,6 +44,7 @@ public class BatchedPstmt implements SpiProfileTransactionEvent { private final SpiTransaction transaction; private long profileStart; + private long timedStart; private int[] results; @@ -112,16 +113,23 @@ public class BatchedPstmt implements SpiProfileTransactionEvent { */ public void executeBatch(boolean getGeneratedKeys) throws SQLException { - this.profileStart = transaction.profileOffset(); + timedStart = System.nanoTime(); + profileStart = transaction.profileOffset(); executeAndCheckRowCounts(); if (isGenKeys && getGeneratedKeys) { getGeneratedKeys(); } postExecute(); close(); + addTimingMetrics(); transaction.profileEvent(this); } + private void addTimingMetrics() { + // just use the first persist request to add batch metrics + list.get(0).addTimingBatch(timedStart, list.size()); + } + @Override public void profile() { // just use the first to add the event @@ -151,7 +159,6 @@ public class BatchedPstmt implements SpiProfileTransactionEvent { String s = "results array error " + results.length + " " + list.size(); throw new SQLException(s); } - // check for concurrency exceptions... for (int i = 0; i < results.length; i++) { list.get(i).checkRowCount(results[i]); diff --git a/src/main/java/io/ebeaninternal/server/persist/dml/DmlBeanPersister.java b/src/main/java/io/ebeaninternal/server/persist/dml/DmlBeanPersister.java index 609ea3ab1..1b646db55 100644 --- a/src/main/java/io/ebeaninternal/server/persist/dml/DmlBeanPersister.java +++ b/src/main/java/io/ebeaninternal/server/persist/dml/DmlBeanPersister.java @@ -70,7 +70,7 @@ public final class DmlBeanPersister implements BeanPersister { return -1; } else { - return handler.execute(); + return handler.executeNoBatch(); } } catch (SQLException e) { diff --git a/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java b/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java index cf299e060..0c004811d 100644 --- a/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java +++ b/src/main/java/io/ebeaninternal/server/persist/dml/DmlHandler.java @@ -92,6 +92,16 @@ public abstract class DmlHandler implements PersistHandler, BindableRequest { @Override public abstract int execute() throws SQLException; + @Override + public final int executeNoBatch() throws SQLException { + final long startNanos = System.nanoTime(); + try { + return execute(); + } finally { + persistRequest.addTimingNoBatch(startNanos); + } + } + /** * Check the rowCount. */ diff --git a/src/main/java/io/ebeaninternal/server/persist/dml/PersistHandler.java b/src/main/java/io/ebeaninternal/server/persist/dml/PersistHandler.java index 299c5e9b1..3efc7fc18 100644 --- a/src/main/java/io/ebeaninternal/server/persist/dml/PersistHandler.java +++ b/src/main/java/io/ebeaninternal/server/persist/dml/PersistHandler.java @@ -22,6 +22,11 @@ interface PersistHandler { */ int execute() throws SQLException; + /** + * Execute now for non-batch with timing. + */ + int executeNoBatch() throws SQLException; + /** * Close resources including underlying preparedStatement. */ diff --git a/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java b/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java index 065d44c8b..8602b53f1 100644 --- a/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java +++ b/src/main/java/io/ebeaninternal/server/profile/DTimedMetric.java @@ -35,6 +35,17 @@ class DTimedMetric implements TimedMetric { this.name = name; } + @Override + public void addBatchSince(long startNanos, int batch) { + if (batch > 0) { + final long totalMicros = (System.nanoTime() - startNanos) / 1000L; + final long mean = totalMicros / batch; + count.add(batch); + total.add(totalMicros); + max.accumulate(mean); + } + } + @Override public void addSinceNanos(long startNanos) { add((System.nanoTime() - startNanos) / 1000L); diff --git a/src/test/java/io/ebeaninternal/server/deploy/BeanIudMetricsTest.java b/src/test/java/io/ebeaninternal/server/deploy/BeanIudMetricsTest.java new file mode 100644 index 000000000..8ca21d56f --- /dev/null +++ b/src/test/java/io/ebeaninternal/server/deploy/BeanIudMetricsTest.java @@ -0,0 +1,79 @@ +package io.ebeaninternal.server.deploy; + +import io.ebean.meta.BasicMetricVisitor; +import io.ebean.meta.MetaTimedMetric; +import io.ebean.meta.MetricType; +import io.ebeaninternal.server.core.PersistRequest; +import org.junit.Test; + +import java.util.List; + +import static org.assertj.core.api.Assertions.assertThat; + +public class BeanIudMetricsTest { + + + @Test + public void addBatch() { + + BeanIudMetrics iudMetrics = new BeanIudMetrics("one"); + + final long startNanos = System.nanoTime() - 10000; + iudMetrics.addBatch(PersistRequest.Type.INSERT, startNanos, 4); + + BasicMetricVisitor basic = new BasicMetricVisitor(); + iudMetrics.visit(basic); + + List timed = basic.getTimedMetrics(); + assertThat(timed).hasSize(1); + + assertThat(timed.get(0).getCount()).isEqualTo(4); + assertThat(timed.get(0).getName()).isEqualTo("iud.one.insertBatch"); + assertThat(timed.get(0).getMetricType()).isEqualTo(MetricType.IUD); + + iudMetrics.addBatch(PersistRequest.Type.UPDATE, startNanos, 1); + iudMetrics.addBatch(PersistRequest.Type.DELETE_SOFT, startNanos, 2); + iudMetrics.addBatch(PersistRequest.Type.DELETE, startNanos, 4); + iudMetrics.addBatch(PersistRequest.Type.DELETE_PERMANENT, startNanos, 8); + iudMetrics.addBatch(PersistRequest.Type.INSERT, startNanos, 16); + + basic = new BasicMetricVisitor(); + iudMetrics.visit(basic); + timed = basic.getTimedMetrics(); + assertThat(timed).hasSize(3); + + assertThat(timed.get(0).getCount()).isEqualTo(16); + assertThat(timed.get(0).getName()).isEqualTo("iud.one.insertBatch"); + assertThat(timed.get(1).getCount()).isEqualTo(3); + assertThat(timed.get(1).getName()).isEqualTo("iud.one.updateBatch"); + assertThat(timed.get(2).getCount()).isEqualTo(12); + assertThat(timed.get(2).getName()).isEqualTo("iud.one.deleteBatch"); + } + + @Test + public void addNoBatch() { + + BeanIudMetrics iudMetrics = new BeanIudMetrics("one"); + + final long startNanos = System.nanoTime() - 10000; + iudMetrics.addNoBatch(PersistRequest.Type.INSERT, startNanos); + iudMetrics.addNoBatch(PersistRequest.Type.UPDATE, startNanos); + iudMetrics.addNoBatch(PersistRequest.Type.DELETE_SOFT, startNanos); + iudMetrics.addNoBatch(PersistRequest.Type.DELETE, startNanos); + iudMetrics.addNoBatch(PersistRequest.Type.DELETE_PERMANENT, startNanos); + + BasicMetricVisitor basic = new BasicMetricVisitor(); + iudMetrics.visit(basic); + + List timed = basic.getTimedMetrics(); + assertThat(timed).hasSize(3); + + assertThat(timed.get(0).getCount()).isEqualTo(1); + assertThat(timed.get(0).getName()).isEqualTo("iud.one.insert"); + assertThat(timed.get(1).getCount()).isEqualTo(2); + assertThat(timed.get(1).getName()).isEqualTo("iud.one.update"); + assertThat(timed.get(2).getCount()).isEqualTo(2); + assertThat(timed.get(2).getName()).isEqualTo("iud.one.delete"); + } + +} diff --git a/src/test/java/io/ebeaninternal/server/profile/DTimedMetricTest.java b/src/test/java/io/ebeaninternal/server/profile/DTimedMetricTest.java index b84800624..bec253420 100644 --- a/src/test/java/io/ebeaninternal/server/profile/DTimedMetricTest.java +++ b/src/test/java/io/ebeaninternal/server/profile/DTimedMetricTest.java @@ -30,4 +30,28 @@ public class DTimedMetricTest { assertThat(stats.getMax()).isEqualTo(stats.getTotal()); assertThat(stats.getBeanCount()).isEqualTo(42); } + + @Test + public void addBatchSince() throws InterruptedException { + + DTimedMetric metric = new DTimedMetric(MetricType.L2, "addSinceNanos"); + + long start = System.nanoTime(); + Thread.sleep(10); + + metric.addBatchSince(start, 5); + + DTimeMetricStats stats = metric.collect(true); + assertThat(stats.getCount()).isEqualTo(5); + assertThat(stats.getTotal()).isGreaterThan(10000); + assertThat(stats.getMax()).isEqualTo(stats.getTotal() / 5); + assertThat(stats.getMax()).isGreaterThan(10000 / 5); + + metric.addBatchSince(start, 2); + + stats = metric.collect(true); + assertThat(stats.getCount()).isEqualTo(2); + assertThat(stats.getTotal()).isGreaterThan(10000); + assertThat(stats.getMax()).isEqualTo(stats.getTotal() / 2); + } }