From 742f3b6dc4899df22f3dec78002fd4888ad74290 Mon Sep 17 00:00:00 2001 From: "robin.bygrave" Date: Tue, 16 May 2023 13:47:27 +1200 Subject: [PATCH] ENH: Add captureMicros and whenCaptured to MetaQueryPlan - captureMicros is the time taken to capture the specific query plan - whenCaptured is the time when the bind values were taken The DefaultQueryPlanListener logging will include these in the output it logs --- .../java/io/ebean/meta/MetaQueryPlan.java | 12 ++++++++++++ .../io/ebeaninternal/api/SpiDbQueryPlan.java | 6 ++++-- .../server/core/DefaultQueryPlanListener.java | 6 +++--- .../server/query/CQueryBindCapture.java | 19 ++++++++++++++----- .../server/query/DQueryPlanOutput.java | 18 +++++++++++++++++- .../query/finder/TestCustomerFinder.java | 14 +++++++------- 6 files changed, 57 insertions(+), 18 deletions(-) diff --git a/ebean-api/src/main/java/io/ebean/meta/MetaQueryPlan.java b/ebean-api/src/main/java/io/ebean/meta/MetaQueryPlan.java index c1ae44a82..7c431022c 100644 --- a/ebean-api/src/main/java/io/ebean/meta/MetaQueryPlan.java +++ b/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(); } diff --git a/ebean-core/src/main/java/io/ebeaninternal/api/SpiDbQueryPlan.java b/ebean-core/src/main/java/io/ebeaninternal/api/SpiDbQueryPlan.java index 135976f54..535232d76 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/api/SpiDbQueryPlan.java +++ b/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); } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java index 039324072..f38b9c8fa 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/core/DefaultQueryPlanListener.java +++ b/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()); } } } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java index 4c72f053e..855d7f010 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryBindCapture.java +++ b/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; diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/DQueryPlanOutput.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/DQueryPlanOutput.java index 642e163e2..c4ffaf9ad 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/DQueryPlanOutput.java +++ b/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; } } diff --git a/ebean-test/src/test/java/org/tests/query/finder/TestCustomerFinder.java b/ebean-test/src/test/java/org/tests/query/finder/TestCustomerFinder.java index 8b0273424..9722adf17 100644 --- a/ebean-test/src/test/java/org/tests/query/finder/TestCustomerFinder.java +++ b/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 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 appliedToPlans = server().metaInfo().queryPlanInit(init); assertThat(appliedToPlans.size()).isGreaterThan(4); @@ -212,9 +212,9 @@ public class TestCustomerFinder extends BaseTestCase { List 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); }