#2268 - Feature request/question: Query execution time for debugging

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

@@ -23,25 +23,16 @@ import javax.persistence.PersistenceException;
 public abstract class AbstractSqlQueryRequest implements CancelableQuery {
 
   protected final SpiSqlBinding query;
-
   protected final SpiEbeanServer server;
-
   protected SpiTransaction transaction;
-
   private boolean createdTransaction;
-
   protected String sql;
-
   protected ResultSet resultSet;
-
   protected String bindLog = "";
-
   protected PreparedStatement pstmt;
-
   protected long startNano;
-
   private final ReentrantLock lock = new ReentrantLock();
-  
+
   /**
    * Create the BeanFindRequest.
    */
@@ -161,7 +152,8 @@ public abstract class AbstractSqlQueryRequest implements CancelableQuery {
         this.bindLog = binder.bind(bindParams, pstmt, conn);
       }
       if (isLogSql()) {
-        transaction.logSql(Str.add(TrimLogSql.trim(sql), "; --bind(", bindLog, ")"));
+        long micros = (System.nanoTime() - startNano) / 1000L;
+        transaction.logSql(Str.add(TrimLogSql.trim(sql), "; --bind(", bindLog, ") --micros(", micros + ")"));
       }
     } finally {
       lock.unlock();

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

@@ -28,11 +28,8 @@ public final class DtoQueryRequest<T> extends AbstractSqlQueryRequest {
   private static final String ENC_PREFIX_UPPER = EncryptAlias.PREFIX.toUpperCase();
 
   private final SpiDtoQuery<T> query;
-
   private final DtoQueryEngine queryEngine;
-
   private DtoQueryPlan plan;
-
   private DataReader dataReader;
 
   DtoQueryRequest(SpiEbeanServer server, DtoQueryEngine engine, SpiDtoQuery<T> query) {

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

@@ -18,11 +18,8 @@ import java.util.function.Predicate;
 public final class RelationalQueryRequest extends AbstractSqlQueryRequest {
 
   private final RelationalQueryEngine queryEngine;
-
   private String[] propertyNames;
-
   private int estimateCapacity;
-
   private int rows;
 
   /**

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

@@ -541,9 +541,13 @@ public class CQuery<T> implements DbReadContext, CancelableQuery, SpiProfileTran
     updateStatistics();
   }
 
+  long micros() {
+    return (System.nanoTime() - startNano) / 1000L;
+  }
+
   private void updateStatistics() {
     try {
-      executionTimeMicros = (System.nanoTime() - startNano) / 1000L;
+      executionTimeMicros = micros();
       if (autoTuneProfiling) {
         profilingListener.collectQueryInfo(objectGraphNode, loadedBeanCount, executionTimeMicros);
       }

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

@@ -79,15 +79,10 @@ public class CQueryEngine {
   private <T> int executeUpdate(OrmQueryRequest<T> request, CQueryUpdate query) {
     try {
       int rows = query.execute();
-
       if (request.isLogSql()) {
-        String logSql = query.getGeneratedSql();
-        logSql = Str.add(logSql, "; --bind(", query.getBindLog(), ") rows:", String.valueOf(rows));
-        request.logSql(logSql);
+        request.logSql(Str.add(query.getGeneratedSql(), "; --bind(", query.getBindLog(), ") --micros(", query.micros() + ") --rows(", rows + ")"));
       }
-
       return rows;
-
     } catch (SQLException e) {
       throw translate(request, query.getBindLog(), query.getGeneratedSql(), e);
     }
@@ -97,7 +92,6 @@ public class CQueryEngine {
    * Build and execute the findSingleAttributeList query.
    */
   public <A> List<A> findSingleAttributeList(OrmQueryRequest<?> request) {
-
     CQueryFetchSingleAttribute rcQuery = queryBuilder.buildFetchAttributeQuery(request);
     request.setCancelableQuery(rcQuery);
     return findAttributeList(request, rcQuery);
@@ -108,14 +102,13 @@ public class CQueryEngine {
     try {
       List<A> list = (List<A>) rcQuery.findList();
       if (request.isLogSql()) {
-        logGeneratedSql(request, rcQuery.getGeneratedSql(), rcQuery.getBindLog());
+        logGeneratedSql(request, rcQuery.getGeneratedSql(), rcQuery.getBindLog(), rcQuery.micros());
       }
       if (request.isLogSummary()) {
         request.getTransaction().logSummary(rcQuery.getSummary());
       }
       if (request.isQueryCachePut()) {
         request.addDependentTables(rcQuery.getDependentTables());
-
         list = Collections.unmodifiableList(list);
         request.putToQueryCache(list);
         if (Boolean.FALSE.equals(request.getQuery().isReadOnly())) {
@@ -123,7 +116,6 @@ public class CQueryEngine {
         }
       }
       return list;
-
     } catch (SQLException e) {
       throw translate(request, rcQuery.getBindLog(), rcQuery.getGeneratedSql(), e);
     }
@@ -139,10 +131,8 @@ public class CQueryEngine {
       String msg = "ERROR executing query, bindLog[" + bindLog + "] error[" + StringHelper.removeNewLines(e.getMessage()) + "]";
       t.logSummary(msg);
     }
-
     // ensure 'rollback' is logged if queryOnly transaction
     t.getConnection();
-
     // build a decent error message for the exception
     String m = "Query threw SQLException:" + e.getMessage() + " Bind values:[" + bindLog + "] Query was:" + sql;
     return dbPlatform.translate(m, e);
@@ -152,46 +142,37 @@ public class CQueryEngine {
    * Build and execute the find Id's query.
    */
   public <A> List<A> findIds(OrmQueryRequest<?> request) {
-
     CQueryFetchSingleAttribute rcQuery = queryBuilder.buildFetchIdsQuery(request);
     request.setCancelableQuery(rcQuery);
     return findAttributeList(request, rcQuery);
   }
 
-  private <T> void logGeneratedSql(OrmQueryRequest<T> request, String sql, String bindLog) {
-    request.logSql(Str.add(sql, "; --bind(", bindLog, ")"));
+  private <T> void logGeneratedSql(OrmQueryRequest<T> request, String sql, String bindLog, long micros) {
+    request.logSql(Str.add(sql, "; --bind(", bindLog, ") --micros(", micros + ")"));
   }
 
   /**
    * Build and execute the row count query.
    */
   public <T> int findCount(OrmQueryRequest<T> request) {
-
     CQueryRowCount rcQuery = queryBuilder.buildRowCountQuery(request);
     request.setCancelableQuery(rcQuery);
     try {
-
       int count = rcQuery.findCount();
-
       if (request.isLogSql()) {
-        logGeneratedSql(request, rcQuery.getGeneratedSql(), rcQuery.getBindLog());
+        logGeneratedSql(request, rcQuery.getGeneratedSql(), rcQuery.getBindLog(), rcQuery.micros());
       }
-
       if (request.isLogSummary()) {
         request.getTransaction().logSummary(rcQuery.getSummary());
       }
-
       if (request.getQuery().isFutureFetch()) {
         request.getTransaction().end();
       }
-
       if (request.isQueryCachePut()) {
         request.addDependentTables(rcQuery.getDependentTables());
         request.putToQueryCache(count);
       }
-
       return count;
-
     } catch (SQLException e) {
       throw translate(request, rcQuery.getBindLog(), rcQuery.getGeneratedSql(), e);
     }
@@ -254,9 +235,7 @@ public class CQueryEngine {
    * Execute the find versions query returning version beans.
    */
   public <T> List<Version<T>> findVersions(OrmQueryRequest<T> request) {
-
     SpiQuery<T> query = request.getQuery();
-
     String sysPeriodLower = getSysPeriodLower(query);
     if (query.isVersionsBetween() && !historySupport.isStandardsBased()) {
       query.where().lt(sysPeriodLower, query.getVersionEnd());
@@ -272,26 +251,21 @@ public class CQueryEngine {
       if (request.isLogSql()) {
         logSql(cquery);
       }
-
       List<Version<T>> versions = cquery.readVersions();
       // just order in memory rather than use NULLS LAST as that
       // is not universally supported, not expect huge list here
       versions.sort(OrderVersionDesc.INSTANCE);
       deriveVersionDiffs(versions, request);
-
       if (request.isLogSummary()) {
         logFindManySummary(cquery);
       }
-
       if (request.isAuditReads()) {
         cquery.auditFindMany();
       }
-
       return versions;
 
     } catch (SQLException e) {
       throw cquery.createPersistenceException(e);
-
     } finally {
       if (cquery != null) {
         cquery.close();
@@ -300,9 +274,7 @@ public class CQueryEngine {
   }
 
   private <T> void deriveVersionDiffs(List<Version<T>> versions, OrmQueryRequest<T> request) {
-
     BeanDescriptor<T> descriptor = request.getBeanDescriptor();
-
     if (!versions.isEmpty()) {
       Version<T> current = versions.get(0);
       if (versions.size() > 1) {
@@ -367,10 +339,8 @@ public class CQueryEngine {
    * Find a list/map/set of beans.
    */
   <T> BeanCollection<T> findMany(OrmQueryRequest<T> request) {
-
     CQuery<T> cquery = queryBuilder.buildQuery(request);
     request.setCancelableQuery(cquery);
-
     try {
       if (defaultFetchSizeFindList > 0) {
         request.setDefaultFetchBuffer(defaultFetchSizeFindList);
@@ -380,30 +350,24 @@ public class CQueryEngine {
         logger.trace("Future fetch already cancelled");
         return null;
       }
-
       if (request.isLogSql()) {
         logSql(cquery);
       }
-
       BeanCollection<T> beanCollection = cquery.readCollection();
       if (request.isLogSummary()) {
         logFindManySummary(cquery);
       }
-
       if (request.isAuditReads()) {
         cquery.auditFindMany();
       }
-
       request.executeSecondaryQueries(false);
       if (request.isQueryCachePut()) {
         request.addDependentTables(cquery.getDependentTables());
       }
-
       return beanCollection;
 
     } catch (SQLException e) {
       throw cquery.createPersistenceException(e);
-
     } finally {
       if (cquery != null) {
         cquery.close();
@@ -416,38 +380,27 @@ public class CQueryEngine {
    */
   @SuppressWarnings("unchecked")
   public <T> T find(OrmQueryRequest<T> request) {
-
     EntityBean bean = null;
-
     CQuery<T> cquery = queryBuilder.buildQuery(request);
     request.setCancelableQuery(cquery);
-
     try {
       cquery.prepareBindExecuteQuery();
-
       if (request.isLogSql()) {
         logSql(cquery);
       }
-
       if (cquery.readBean()) {
         bean = cquery.next();
       }
-
       if (request.isLogSummary()) {
         logFindBeanSummary(cquery);
       }
-
       if (request.isAuditReads()) {
         cquery.auditFind(bean);
       }
-
       request.executeSecondaryQueries(false);
-
       return (T) bean;
-
     } catch (SQLException e) {
       throw cquery.createPersistenceException(e);
-
     } finally {
       cquery.close();
     }
@@ -457,17 +410,13 @@ public class CQueryEngine {
    * Log the generated SQL to the transaction log.
    */
   private void logSql(CQuery<?> query) {
-
-    String sql = query.getGeneratedSql();
-    sql = Str.add(sql, "; --bind(", query.getBindLog(), ")");
-    query.getTransaction().logSql(sql);
+    query.getTransaction().logSql(Str.add(query.getGeneratedSql(), "; --bind(", query.getBindLog(), ") --micros(", query.micros() + ")"));
   }
 
   /**
    * Log the FindById summary to the transaction log.
    */
   private void logFindBeanSummary(CQuery<?> q) {
-
     SpiQuery<?> query = q.getQueryRequest().getQuery();
     String loadMode = query.getLoadMode();
     String loadDesc = query.getLoadDescription();
@@ -504,7 +453,6 @@ public class CQueryEngine {
     msg.append("exeMicros[").append(q.getQueryExecutionTimeMicros());
     msg.append("] rows[").append(q.getLoadedRowDetail());
     msg.append("] bind[").append(q.getBindLog()).append("]");
-
     q.getTransaction().logSummary(msg.toString());
   }
 
@@ -512,7 +460,6 @@ public class CQueryEngine {
    * Log the FindMany to the transaction log.
    */
   private void logFindManySummary(CQuery<?> q) {
-
     SpiQuery<?> query = q.getQueryRequest().getQuery();
     String loadMode = query.getLoadMode();
     String loadDesc = query.getLoadDescription();
@@ -551,7 +498,6 @@ public class CQueryEngine {
     msg.append("] rows[").append(q.getLoadedRowDetail());
     msg.append("] predicates[").append(q.getLogWhereSql());
     msg.append("] bind[").append(q.getBindLog()).append("]");
-
     q.getTransaction().logSummary(msg.toString());
   }
 }

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

@@ -29,45 +29,19 @@ class CQueryFetchSingleAttribute implements SpiProfileTransactionEvent, Cancelab
   private static final Logger logger = LoggerFactory.getLogger(CQueryFetchSingleAttribute.class);
 
   private final CQueryPlan queryPlan;
-
-  /**
-   * The overall find request wrapper object.
-   */
   private final OrmQueryRequest<?> request;
-
   private final BeanDescriptor<?> desc;
-
   private final SpiQuery<?> query;
-
-  /**
-   * Where clause predicates.
-   */
   private final CQueryPredicates predicates;
-
-  /**
-   * The final sql that is generated.
-   */
   private final String sql;
-
   private RsetDataReader dataReader;
-
-  /**
-   * The statement used to create the resultSet.
-   */
   private PreparedStatement pstmt;
-
   private String bindLog;
-
   private long executionTimeMicros;
-
   private int rowCount;
-
   private final ScalarDataReader<?> reader;
-
   private final boolean containsCounts;
-
   private long profileOffset;
-  
   private final ReentrantLock lock = new ReentrantLock();
 
   /**
@@ -95,19 +69,20 @@ class CQueryFetchSingleAttribute implements SpiProfileTransactionEvent, Cancelab
       .append("] type[").append(desc.getName())
       .append("] predicates[").append(predicates.getLogWhereSql())
       .append("] bind[").append(bindLog).append("]");
-
     return sb.toString();
   }
 
+  long micros() {
+    return executionTimeMicros;
+  }
+
   /**
    * Execute the query returning the row count.
    */
   List<Object> findList() throws SQLException {
-
     long startNano = System.nanoTime();
     try {
       prepareExecute();
-
       List<Object> result = new ArrayList<>();
       while (dataReader.next()) {
         Object value = reader.read(dataReader);
@@ -117,16 +92,13 @@ class CQueryFetchSingleAttribute implements SpiProfileTransactionEvent, Cancelab
         result.add(value);
         rowCount++;
       }
-
       executionTimeMicros = (System.nanoTime() - startNano) / 1000L;
       request.slowQueryCheck(executionTimeMicros, rowCount);
       if (queryPlan.executionTime(executionTimeMicros)) {
         queryPlan.captureBindForQueryPlan(predicates, executionTimeMicros);
       }
       getTransaction().profileEvent(this);
-
       return result;
-
     } finally {
       close();
     }
@@ -158,14 +130,12 @@ class CQueryFetchSingleAttribute implements SpiProfileTransactionEvent, Cancelab
       profileOffset = t.profileOffset();
       Connection conn = t.getInternalConnection();
       pstmt = conn.prepareStatement(sql);
-  
       if (query.getBufferFetchSizeHint() > 0) {
         pstmt.setFetchSize(query.getBufferFetchSizeHint());
       }
       if (query.getTimeout() > 0) {
         pstmt.setQueryTimeout(query.getTimeout());
       }
-  
       bindLog = predicates.bind(pstmt, conn);
     } finally {
       lock.unlock();

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

@@ -22,44 +22,17 @@ import java.util.concurrent.locks.ReentrantLock;
 class CQueryRowCount implements SpiProfileTransactionEvent, CancelableQuery {
 
   private final CQueryPlan queryPlan;
-
-  /**
-   * The overall find request wrapper object.
-   */
   private final OrmQueryRequest<?> request;
-
   private final BeanDescriptor<?> desc;
-
   private final SpiQuery<?> query;
-
-  /**
-   * Where clause predicates.
-   */
   private final CQueryPredicates predicates;
-
-  /**
-   * The final sql that is generated.
-   */
   private final String sql;
-
-  /**
-   * The resultSet that is read and converted to objects.
-   */
   private ResultSet rset;
-
-  /**
-   * The statement used to create the resultSet.
-   */
   private PreparedStatement pstmt;
-
   private String bindLog;
-
   private long executionTimeMicros;
-
   private int rowCount;
-
   private long profileOffset;
-  
   private final ReentrantLock lock = new ReentrantLock();
 
   /**
@@ -104,11 +77,14 @@ class CQueryRowCount implements SpiProfileTransactionEvent, CancelableQuery {
     return sql;
   }
 
+  long micros() {
+    return executionTimeMicros;
+  }
+
   /**
    * Execute the query returning the row count.
    */
   public int findCount() throws SQLException {
-
     long startNano = System.nanoTime();
     try {
       SpiTransaction t = getTransaction();
@@ -118,24 +94,19 @@ class CQueryRowCount implements SpiProfileTransactionEvent, CancelableQuery {
       try {
         query.checkCancelled();
         pstmt = conn.prepareStatement(sql);
-
         if (query.getTimeout() > 0) {
           pstmt.setQueryTimeout(query.getTimeout());
         }
-
         bindLog = predicates.bind(pstmt, conn);
       } finally {
         lock.unlock();
       }
       rset = pstmt.executeQuery();
       query.checkCancelled();
-      
       if (!rset.next()) {
         throw new PersistenceException("Expecting 1 row but got none?");
       }
-
       rowCount = rset.getInt(1);
-
       executionTimeMicros = (System.nanoTime() - startNano) / 1000L;
       request.slowQueryCheck(executionTimeMicros, rowCount);
       if (queryPlan.executionTime(executionTimeMicros)) {
@@ -143,7 +114,6 @@ class CQueryRowCount implements SpiProfileTransactionEvent, CancelableQuery {
       }
       t.profileEvent(this);
       return rowCount;
-
     } finally {
       close();
     }

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

@@ -19,36 +19,18 @@ import java.util.concurrent.locks.ReentrantLock;
 class CQueryUpdate implements SpiProfileTransactionEvent, CancelableQuery {
 
   private final CQueryPlan queryPlan;
-
   private final OrmQueryRequest<?> request;
-
   private final BeanDescriptor<?> desc;
-
   private final SpiQuery<?> query;
-
-  /**
-   * Where clause predicates.
-   */
   private final CQueryPredicates predicates;
-
-  /**
-   * The final sql that is generated.
-   */
   private final String sql;
-
-  /**
-   * The statement used to create the resultSet.
-   */
   private PreparedStatement pstmt;
-
   private String bindLog;
-
   private int rowCount;
-
   private long profileOffset;
-
+  private long executionTimeMicros;
   private final ReentrantLock lock = new ReentrantLock();
-  
+
   /**
    * Create the Sql select based on the request.
    */
@@ -80,7 +62,6 @@ class CQueryUpdate implements SpiProfileTransactionEvent, CancelableQuery {
    * Execute the update or delete statement returning the row count.
    */
   public int execute() throws SQLException {
-
     long startNano = System.nanoTime();
     try {
       SpiTransaction t = getTransaction();
@@ -90,19 +71,16 @@ class CQueryUpdate implements SpiProfileTransactionEvent, CancelableQuery {
       try {
         query.checkCancelled();
         pstmt = conn.prepareStatement(sql);
-
         if (query.getTimeout() > 0) {
           pstmt.setQueryTimeout(query.getTimeout());
         }
-
         bindLog = predicates.bind(pstmt, conn);
       } finally {
         lock.unlock();
       }
       rowCount = pstmt.executeUpdate();
       query.checkCancelled();
-      
-      long executionTimeMicros = (System.nanoTime() - startNano) / 1000L;
+      executionTimeMicros = (System.nanoTime() - startNano) / 1000L;
       request.slowQueryCheck(executionTimeMicros, rowCount);
       if (queryPlan.executionTime(executionTimeMicros)) {
         queryPlan.captureBindForQueryPlan(predicates, executionTimeMicros);
@@ -115,6 +93,10 @@ class CQueryUpdate implements SpiProfileTransactionEvent, CancelableQuery {
     }
   }
 
+  long micros() {
+    return executionTimeMicros;
+  }
+
   private SpiTransaction getTransaction() {
     return request.getTransaction();
   }