Merge pull request #3372 from ebean-orm/feature/1857-SlowQueryBindCap…

…ture

#1857 Add bind values capture for SlowQueryEvent / SlowQueryListener

ebean-api/src/main/java/io/ebean/config/SlowQueryEvent.java

@@ -1,50 +1,29 @@
 package io.ebean.config;
 
+import io.ebean.ProfileLocation;
 import io.ebean.bean.ObjectGraphNode;
 
+import java.util.List;
+
 /**
- * Slow query event.
+ * The data for the slow query.
  */
-public class SlowQueryEvent {
-
-  private final String sql;
-
-  private final long timeMillis;
-
-  private final int rowCount;
-
-  private final ObjectGraphNode originNode;
-
-  /**
-   * Construct with the SQL and execution time in millis.
-   */
-  public SlowQueryEvent(String sql, long timeMillis, int rowCount, ObjectGraphNode originNode) {
-    this.sql = sql;
-    this.timeMillis = timeMillis;
-    this.rowCount = rowCount;
-    this.originNode = originNode;
-  }
+public interface SlowQueryEvent {
 
   /**
    * Return the SQL for the slow query.
    */
-  public String getSql() {
-    return sql;
-  }
+  String getSql();
 
   /**
    * Return the execution time in millis.
    */
-  public long getTimeMillis() {
-    return timeMillis;
-  }
+  long getTimeMillis();
 
   /**
    * Return the total row count associated with the query.
    */
-  public int getRowCount() {
-    return rowCount;
-  }
+  int getRowCount();
 
   /**
    * Return the origin point for the root query.
@@ -53,7 +32,20 @@ public int getRowCount() {
    * shows the code that invoked the query.
    * </p>
    */
-  public ObjectGraphNode getOriginNode() {
-    return originNode;
-  }
+  ObjectGraphNode getOriginNode();
+
+  /**
+   * Return the bind parameters.
+   */
+  List<Object> getBindParams();
+
+  /**
+   * Return the label.
+   */
+  String getLabel();
+
+  /**
+   * Return the profile location.
+   */
+  ProfileLocation getProfileLocation();
 }

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

@@ -84,7 +84,7 @@ public interface SpiExpression extends Expression {
    *
    * @param request the associated request.
    */
-  void addBindValues(SpiExpressionRequest request);
+  void addBindValues(SpiExpressionBind request);
 
   /**
    * Validate all the properties/paths associated with this expression.

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

@@ -0,0 +1,29 @@
+package io.ebeaninternal.api;
+
+import io.ebeaninternal.server.deploy.BeanDescriptor;
+
+/**
+ * Expression bind values capture.
+ */
+public interface SpiExpressionBind {
+
+  /**
+   * Return the bean descriptor for the root type.
+   */
+  BeanDescriptor<?> descriptor();
+
+  /**
+   * Add an encryption key to bind to this request.
+   */
+  void addBindEncryptKey(Object encryptKey);
+
+  /**
+   * Add a bind value to this request.
+   */
+  void addBindValue(Object bindValue);
+
+  /**
+   * Escapes a string to use it as exact match in Like clause.
+   */
+  String escapeLikeString(String value);
+}

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

@@ -1,7 +1,6 @@
 package io.ebeaninternal.api;
 
 import io.ebeaninternal.server.core.SpiOrmQueryRequest;
-import io.ebeaninternal.server.deploy.BeanDescriptor;
 import io.ebeaninternal.server.expression.platform.DbExpressionHandler;
 import io.ebeaninternal.server.expression.platform.DbExpressionRequest;
 
@@ -10,7 +9,7 @@
 /**
  * Request object used for gathering expression sql and bind values.
  */
-public interface SpiExpressionRequest extends DbExpressionRequest {
+public interface SpiExpressionRequest extends SpiExpressionBind, DbExpressionRequest {
 
   /**
    * Return the DB specific handler for JSON and ARRAY expressions.
@@ -22,11 +21,6 @@ public interface SpiExpressionRequest extends DbExpressionRequest {
    */
   String parseDeploy(String logicalProp);
 
-  /**
-   * Return the bean descriptor for the root type.
-   */
-  BeanDescriptor<?> descriptor();
-
   /**
    * Return the associated QueryRequest.
    */
@@ -58,16 +52,6 @@ public interface SpiExpressionRequest extends DbExpressionRequest {
    */
   SpiExpressionRequest parse(String expression);
 
-  /**
-   * Add an encryption key to bind to this request.
-   */
-  void addBindEncryptKey(Object encryptKey);
-
-  /**
-   * Add a bind value to this request.
-   */
-  void addBindValue(Object bindValue);
-
   /**
    * Return the accumulated expression sql for all expressions in this request.
    */
@@ -88,11 +72,6 @@ public interface SpiExpressionRequest extends DbExpressionRequest {
    */
   void appendLike(boolean rawLikeExpression);
 
-  /**
-   * Escapes a string to use it as exact match in Like clause.
-   */
-  String escapeLikeString(String value);
-
   /**
    * Append IN expression taking into account platform and type support for Multi-value.
    */

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

@@ -0,0 +1,70 @@
+package io.ebeaninternal.server.core;
+
+import io.ebean.ProfileLocation;
+import io.ebean.bean.ObjectGraphNode;
+import io.ebean.config.SlowQueryEvent;
+
+import java.util.List;
+
+/**
+ * Slow query event.
+ */
+final class DSlowQueryEvent implements SlowQueryEvent {
+
+  private final String sql;
+  private final long timeMillis;
+  private final int rowCount;
+  private final ObjectGraphNode originNode;
+  private final List<Object> bindParams;
+  private final String label;
+  private final ProfileLocation profileLocation;
+
+  /**
+   * Construct with the SQL and execution time in millis.
+   */
+  DSlowQueryEvent(String sql, long timeMillis, int rowCount, ObjectGraphNode originNode,
+                         List<Object> bindParams, String label, ProfileLocation profileLocation) {
+    this.sql = sql;
+    this.timeMillis = timeMillis;
+    this.rowCount = rowCount;
+    this.originNode = originNode;
+    this.bindParams = bindParams;
+    this.profileLocation = profileLocation;
+    this.label = label != null ? label : profileLocation == null ? null : profileLocation.label();
+  }
+
+  @Override
+  public String getSql() {
+    return sql;
+  }
+
+  @Override
+  public long getTimeMillis() {
+    return timeMillis;
+  }
+
+  @Override
+  public int getRowCount() {
+    return rowCount;
+  }
+
+  @Override
+  public ObjectGraphNode getOriginNode() {
+    return originNode;
+  }
+
+  @Override
+  public List<Object> getBindParams() {
+    return bindParams;
+  }
+
+  @Override
+  public String getLabel() {
+    return label;
+  }
+
+  @Override
+  public ProfileLocation getProfileLocation() {
+    return profileLocation;
+  }
+}

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

@@ -2184,7 +2184,9 @@ public SpiJsonContext jsonExtended() {
   @Override
   public void slowQueryCheck(long timeMicros, int rowCount, SpiQuery<?> query) {
     if (timeMicros > slowQueryMicros && slowQueryListener != null) {
-      slowQueryListener.process(new SlowQueryEvent(query.getGeneratedSql(), timeMicros / 1000L, rowCount, query.parentNode()));
+      List<Object> bindParams = new SlowQueryBindCapture(query).capture();
+      slowQueryListener.process(new DSlowQueryEvent(query.getGeneratedSql(), timeMicros / 1000L, rowCount,
+        query.parentNode(), bindParams, query.label(), query.profileLocation()));
     }
   }
 

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

@@ -1,10 +1,12 @@
 package io.ebeaninternal.server.core;
 
 import io.avaje.applog.AppLog;
-import io.ebean.bean.ObjectGraphNode;
+import io.ebean.ProfileLocation;
 import io.ebean.config.SlowQueryEvent;
 import io.ebean.config.SlowQueryListener;
 
+import java.util.List;
+
 import static java.lang.System.Logger.Level.WARNING;
 
 /**
@@ -16,11 +18,10 @@ final class DefaultSlowQueryListener implements SlowQueryListener {
 
   @Override
   public void process(SlowQueryEvent event) {
-    String firstStack = "";
-    ObjectGraphNode node = event.getOriginNode();
-    if (node != null) {
-      firstStack = node.origin().top();
-    }
-    log.log(WARNING, "Slow query warning - millis:{0} rows:{1} caller[{2}] sql[{3}]", event.getTimeMillis(), event.getRowCount(), firstStack, event.getSql());
+    ProfileLocation profileLocation = event.getProfileLocation();
+    String loc = profileLocation == null ? "" : profileLocation.fullLocation();
+    List<Object> bindParams = event.getBindParams();
+    log.log(WARNING, "Slow query warning - millis:{0} rows:{1} location:{2} sql[{3}] params{4}",
+      event.getTimeMillis(), event.getRowCount(), loc, event.getSql(), bindParams);
   }
 }

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

@@ -0,0 +1,71 @@
+package io.ebeaninternal.server.core;
+
+import io.ebeaninternal.api.BindParams;
+import io.ebeaninternal.api.SpiExpressionBind;
+import io.ebeaninternal.api.SpiExpressionList;
+import io.ebeaninternal.api.SpiQuery;
+import io.ebeaninternal.server.deploy.BeanDescriptor;
+import io.ebeaninternal.server.persist.MultiValueWrapper;
+
+import java.util.ArrayList;
+import java.util.List;
+
+final class SlowQueryBindCapture implements SpiExpressionBind {
+
+  private final SpiQuery<?> query;
+  private final List<Object> bindParams = new ArrayList<>();
+
+  SlowQueryBindCapture(SpiQuery<?> query) {
+    this.query = query;
+  }
+
+  List<Object> capture() {
+    var params = query.bindParams();
+    if (params != null) {
+      var positionedParameters = params.positionedParameters();
+      for (BindParams.Param param : positionedParameters) {
+        if (param.isInParam()) {
+          add(param.inValue());
+        }
+      }
+    }
+    Object id = query.getId();
+    if (id != null) {
+      add(id);
+    }
+    SpiExpressionList<?> spiExpressionList = query.whereExpressions();
+    if (spiExpressionList != null) {
+      spiExpressionList.addBindValues(this);
+    }
+    return bindParams;
+  }
+
+  private void add(Object value) {
+    if (value instanceof MultiValueWrapper) {
+      var mvw = (MultiValueWrapper) value;
+      bindParams.add(mvw.getValues());
+    } else {
+      bindParams.add(value);
+    }
+  }
+
+  @Override
+  public BeanDescriptor<?> descriptor() {
+    return query.descriptor();
+  }
+
+  @Override
+  public void addBindValue(Object bindValue) {
+    add(bindValue);
+  }
+
+  @Override
+  public void addBindEncryptKey(Object encryptKey) {
+    bindParams.add("*");
+  }
+
+  @Override
+  public String escapeLikeString(String value) {
+    return query.descriptor().ebeanServer().databasePlatform().escapeLikeString(value);
+  }
+}

ebean-core/src/main/java/io/ebeaninternal/server/deploy/id/IdBinder.java

@@ -1,6 +1,7 @@
 package io.ebeaninternal.server.deploy.id;
 
 import io.ebean.bean.EntityBean;
+import io.ebeaninternal.api.SpiExpressionBind;
 import io.ebeaninternal.api.SpiExpressionRequest;
 import io.ebeaninternal.server.core.DefaultSqlUpdate;
 import io.ebeaninternal.server.deploy.BeanProperty;
@@ -143,7 +144,7 @@ default int size() {
   /**
    * Binds multiple id value to a request.
    */
-  void addBindValues(SpiExpressionRequest request, Collection<?> ids);
+  void addBindValues(SpiExpressionBind request, Collection<?> ids);
 
   /**
    * Return the sql for binding the id using an IN clause.

ebean-core/src/main/java/io/ebeaninternal/server/deploy/id/IdBinderEmbedded.java

@@ -2,6 +2,7 @@
 
 import io.ebean.bean.EntityBean;
 import io.ebean.util.SplitName;
+import io.ebeaninternal.api.SpiExpressionBind;
 import io.ebeaninternal.api.SpiExpressionRequest;
 import io.ebeaninternal.server.core.DefaultSqlUpdate;
 import io.ebeaninternal.server.deploy.BeanDescriptor;
@@ -269,7 +270,7 @@ public void addBindValues(DefaultSqlUpdate sqlUpdate, Collection<?> values) {
   }
 
   @Override
-  public void addBindValues(SpiExpressionRequest request, Collection<?> values) {
+  public void addBindValues(SpiExpressionBind request, Collection<?> values) {
     for (Object value : values) {
       final EntityBean bean = (EntityBean) value;
       for (BeanProperty prop : props) {