#1865 - ENH: Add metric collection for ORM insert update and delete

src/main/java/io/ebean/meta/MetricType.java

@@ -10,6 +10,11 @@ public enum MetricType {
    */
   TXN,
 
+  /**
+   * ORM Insert Update or Delete.
+   */
+  IUD,
+
   /**
    * ORM queries.
    */

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

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

src/main/java/io/ebeaninternal/server/core/PersistRequestBean.java

@@ -229,6 +229,16 @@ public final class PersistRequestBean<T> 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.
    */

src/main/java/io/ebeaninternal/server/deploy/BeanDescriptor.java

@@ -143,6 +143,8 @@ public class BeanDescriptor<T> implements BeanType<T>, 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<T> implements BeanType<T>, 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<T> implements BeanType<T>, 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<T> implements BeanType<T>, 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()));

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);
+  }
+}

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);
 }

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]);

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) {

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

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

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);

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<MetaTimedMetric> 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<MetaTimedMetric> 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");
+  }
+
+}

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);
+  }
 }