Merge pull request #3055 from ebean-orm/feature/queryPlanCaptureMicros

ENH: Add captureMicros and whenCaptured to MetaQueryPlan

ebean-api/src/main/java/io/ebean/meta/MetaQueryPlan.java

@@ -2,6 +2,8 @@ package io.ebean.meta;
 
 import io.ebean.ProfileLocation;
 
+import java.time.Instant;
+
 /**
  * Meta data for captured query plan.
  */
@@ -51,4 +53,14 @@ public interface MetaQueryPlan {
    * Return the total count of times bind capture has occurred.
    */
   long captureCount();
+
+  /**
+   * Return the time taken to capture this plan in microseconds.
+   */
+  long captureMicros();
+
+  /**
+   * Return the instant when the bind values were captured.
+   */
+  Instant whenCaptured();
 }

ebean-core/src/main/java/io/ebeaninternal/api/SpiDbQueryPlan.java

@@ -2,14 +2,16 @@ package io.ebeaninternal.api;
 
 import io.ebean.meta.MetaQueryPlan;
 
+import java.time.Instant;
+
 /**
  * Internal database query plan being capture.
  */
 public interface SpiDbQueryPlan extends MetaQueryPlan {
 
   /**
-   * Extend with queryTimeMicros and captureCount.
+   * Extend with queryTimeMicros, captureCount, captureMicros and when the bind values were captured.
    */
-  SpiDbQueryPlan with(long queryTimeMicros, long captureCount);
+  SpiDbQueryPlan with(long queryTimeMicros, long captureCount, long captureMicros, Instant whenCaptured);
 
 }

ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java

@@ -18,9 +18,9 @@ final class DefaultQueryPlanListener implements QueryPlanListener {
     // better to log this in JSON form?
     String dbName = capture.database().name();
     for (MetaQueryPlan plan : capture.plans()) {
-      log.log(INFO, "queryPlan  db:{0} label:{1} queryTimeMicros:{2} loc:{3} sql:{4} bind:{5} plan:{6}",
-        dbName, plan.label(), plan.queryTimeMicros(), plan.profileLocation(),
-        plan.sql(), plan.bind(), plan.plan());
+      log.log(INFO, "queryPlan  db:{0} label:{1} queryTimeMicros:{2} captureMicros:{3} whenCaptured:{4} captureCount:{5} loc:{6} sql:{7} bind:{8} plan:{9}",
+        dbName, plan.label(), plan.queryTimeMicros(), plan.captureMicros(), plan.whenCaptured(), plan.captureCount(),
+        plan.profileLocation(), plan.sql(), plan.bind(), plan.plan());
     }
   }
 }

ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java

@@ -5,6 +5,8 @@ import io.ebeaninternal.api.SpiQueryBindCapture;
 import io.ebeaninternal.api.SpiQueryPlan;
 import io.ebeaninternal.server.bind.capture.BindCapture;
 
+import java.time.Instant;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.locks.ReentrantLock;
 
 final class CQueryBindCapture implements SpiQueryBindCapture {
@@ -53,9 +55,14 @@ final class CQueryBindCapture implements SpiQueryBindCapture {
 
   @Override
   public void queryPlanInit(long thresholdMicros) {
-    // effective enable bind capture for this plan
-    this.thresholdMicros = thresholdMicros;
-    this.captureCount = 0;
+    lock.lock();
+    try {
+      // effective enable bind capture for this plan
+      this.thresholdMicros = thresholdMicros;
+      this.captureCount = 0;
+    } finally {
+      lock.unlock();
+    }
   }
 
   /**
@@ -67,11 +74,13 @@ final class CQueryBindCapture implements SpiQueryBindCapture {
       return false;
     }
 
+    final Instant whenCaptured = Instant.ofEpochMilli(this.lastBindCapture);
     final BindCapture last = this.bindCapture;
-
+    final long startNanos = System.nanoTime();
     SpiDbQueryPlan queryPlan = manager.collectPlan(request.connection(), this.queryPlan, last);
     if (queryPlan != null) {
-      request.add(queryPlan.with(queryTimeMicros, captureCount));
+      final long captureMicros = TimeUnit.MICROSECONDS.convert(System.nanoTime() - startNanos, TimeUnit.NANOSECONDS);
+      request.add(queryPlan.with(queryTimeMicros, captureCount, captureMicros, whenCaptured));
       // effectively turn off bind capture for this plan
       thresholdMicros = Long.MAX_VALUE;
       return true;

ebean-core/src/main/java/io/ebeaninternal/server/query/DQueryPlanOutput.java

@@ -4,6 +4,8 @@ import io.ebean.ProfileLocation;
 import io.ebean.meta.MetaQueryPlan;
 import io.ebeaninternal.api.SpiDbQueryPlan;
 
+import java.time.Instant;
+
 /**
  * Captured query plan details.
  */
@@ -19,6 +21,8 @@ final class DQueryPlanOutput implements MetaQueryPlan, SpiDbQueryPlan {
   private final String hash;
   private long queryTimeMicros;
   private long captureCount;
+  private long captureMicros;
+  private Instant whenCaptured;
 
   DQueryPlanOutput(Class<?> beanType, String label, String hash, String sql, ProfileLocation profileLocation, String bind, String plan) {
     this.beanType = beanType;
@@ -97,6 +101,16 @@ final class DQueryPlanOutput implements MetaQueryPlan, SpiDbQueryPlan {
     return captureCount;
   }
 
+  @Override
+  public long captureMicros() {
+    return captureMicros;
+  }
+
+  @Override
+  public Instant whenCaptured() {
+    return whenCaptured;
+  }
+
   @Override
   public String toString() {
     return " BeanType:" + ((beanType == null) ? "" : beanType.getSimpleName()) + " planHash:" + hash + " label:" + label + " queryTimeMicros:" + queryTimeMicros + " captureCount:" + captureCount + "\n SQL:" + sql + "\nBIND:" + bind + "\nPLAN:" + plan;
@@ -106,9 +120,11 @@ final class DQueryPlanOutput implements MetaQueryPlan, SpiDbQueryPlan {
    * Additionally set the query execution time and the number of bind captures.
    */
   @Override
-  public DQueryPlanOutput with(long queryTimeMicros, long captureCount) {
+  public DQueryPlanOutput with(long queryTimeMicros, long captureCount, long captureMicros, Instant whenCaptured) {
     this.queryTimeMicros = queryTimeMicros;
     this.captureCount = captureCount;
+    this.captureMicros = captureMicros;
+    this.whenCaptured = whenCaptured;
     return this;
   }
 }

ebean-test/src/test/java/org/tests/query/finder/TestCustomerFinder.java

@@ -170,20 +170,20 @@ public class TestCustomerFinder extends BaseTestCase {
 
     ResetBasicData.reset();
 
-    // change default collect query plan threshold to 200 micros
+    // change default collect query plan threshold to 20 micros
     QueryPlanInit init0 = new QueryPlanInit();
     init0.setAll(true);
-    init0.thresholdMicros(2);
+    init0.thresholdMicros(20);
     final List<MetaQueryPlan> plans = server().metaInfo().queryPlanInit(init0);
     assertThat(plans.size()).isGreaterThan(1);
 
     // the server has some plans
     runQueries();
 
-    // change query plan threshold to 100 micros
+    // change query plan threshold to 10 micros
     QueryPlanInit init = new QueryPlanInit();
     init.setAll(true);
-    init.thresholdMicros(1);
+    init.thresholdMicros(10);
     final List<MetaQueryPlan> appliedToPlans = server().metaInfo().queryPlanInit(init);
     assertThat(appliedToPlans.size()).isGreaterThan(4);
 
@@ -212,9 +212,9 @@ public class TestCustomerFinder extends BaseTestCase {
     List<MetaQueryPlan> plans0 = server().metaInfo().queryPlanCollectNow(request);
     assertThat(plans0).isNotEmpty();
 
-    for (MetaQueryPlan plan : plans) {
-      logger.info("queryPlan label:{}, queryTimeMicros:{} loc:{} sql:{} bind:{} plan:{}",
-        plan.label(), plan.queryTimeMicros(), plan.profileLocation(),
+    for (MetaQueryPlan plan : plans0) {
+      logger.info("queryPlan label:{}, queryTimeMicros:{} captureMicros:{} whenCaptured:{} captureCount:{} loc:{} sql:{} bind:{} plan:{}",
+        plan.label(), plan.queryTimeMicros(), plan.captureMicros(), plan.whenCaptured(), plan.captureCount(), plan.profileLocation(),
         plan.sql(), plan.bind(), plan.plan());
       System.out.println(plan);
     }