diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/AbstractSqlQueryRequest.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/AbstractSqlQueryRequest.java index 67844c631..a88f1bbe9 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/core/AbstractSqlQueryRequest.java +++ b/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(); diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/DtoQueryRequest.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/DtoQueryRequest.java index 2b1a55f6e..c023f2d0d 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/core/DtoQueryRequest.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/core/DtoQueryRequest.java @@ -28,11 +28,8 @@ public final class DtoQueryRequest extends AbstractSqlQueryRequest { private static final String ENC_PREFIX_UPPER = EncryptAlias.PREFIX.toUpperCase(); private final SpiDtoQuery query; - private final DtoQueryEngine queryEngine; - private DtoQueryPlan plan; - private DataReader dataReader; DtoQueryRequest(SpiEbeanServer server, DtoQueryEngine engine, SpiDtoQuery query) { diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/core/RelationalQueryRequest.java b/ebean-core/src/main/java/io/ebeaninternal/server/core/RelationalQueryRequest.java index a5130ef22..ef3874008 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/core/RelationalQueryRequest.java +++ b/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; /** diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQuery.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQuery.java index e7674a31c..7fc636af0 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQuery.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQuery.java @@ -541,9 +541,13 @@ public class CQuery 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); } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryEngine.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryEngine.java index a1a211c0a..03074b43f 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryEngine.java +++ b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryEngine.java @@ -79,15 +79,10 @@ public class CQueryEngine { private int executeUpdate(OrmQueryRequest 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 List findSingleAttributeList(OrmQueryRequest request) { - CQueryFetchSingleAttribute rcQuery = queryBuilder.buildFetchAttributeQuery(request); request.setCancelableQuery(rcQuery); return findAttributeList(request, rcQuery); @@ -108,14 +102,13 @@ public class CQueryEngine { try { List list = (List) 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 List findIds(OrmQueryRequest request) { - CQueryFetchSingleAttribute rcQuery = queryBuilder.buildFetchIdsQuery(request); request.setCancelableQuery(rcQuery); return findAttributeList(request, rcQuery); } - private void logGeneratedSql(OrmQueryRequest request, String sql, String bindLog) { - request.logSql(Str.add(sql, "; --bind(", bindLog, ")")); + private void logGeneratedSql(OrmQueryRequest request, String sql, String bindLog, long micros) { + request.logSql(Str.add(sql, "; --bind(", bindLog, ") --micros(", micros + ")")); } /** * Build and execute the row count query. */ public int findCount(OrmQueryRequest 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 List> findVersions(OrmQueryRequest request) { - SpiQuery 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> 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 void deriveVersionDiffs(List> versions, OrmQueryRequest request) { - BeanDescriptor descriptor = request.getBeanDescriptor(); - if (!versions.isEmpty()) { Version current = versions.get(0); if (versions.size() > 1) { @@ -367,10 +339,8 @@ public class CQueryEngine { * Find a list/map/set of beans. */ BeanCollection findMany(OrmQueryRequest request) { - CQuery 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 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 find(OrmQueryRequest request) { - EntityBean bean = null; - CQuery 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()); } } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java index b68813bd4..a89cd28fa 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryFetchSingleAttribute.java +++ b/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 findList() throws SQLException { - long startNano = System.nanoTime(); try { prepareExecute(); - List 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(); diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java index 248fa9058..0c1df9483 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryRowCount.java +++ b/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(); } diff --git a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java b/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java index eec5d2e6f..302b1bcf0 100644 --- a/ebean-core/src/main/java/io/ebeaninternal/server/query/CQueryUpdate.java +++ b/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(); }