This is an automated email from the ASF dual-hosted git repository.
haridsv pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/phoenix.git
The following commit(s) were added to refs/heads/master by this push:
new d1ad2be352 PHOENIX-7535 Capture time spent in stages of exceuteQuery
call (#2219)
d1ad2be352 is described below
commit d1ad2be35205c99e27458c9c88f52ae0543f0197
Author: Rahul Kumar <[email protected]>
AuthorDate: Thu Jul 17 18:37:25 2025 +0530
PHOENIX-7535 Capture time spent in stages of exceuteQuery call (#2219)
* PHOENIX-7535 Capture time spent in stages of exceuteQuery call
---------
Co-authored-by: Rahul Kumar
<[email protected]>
---
.../org/apache/phoenix/jdbc/PhoenixStatement.java | 22 ++++++-
.../org/apache/phoenix/monitoring/MetricType.java | 5 ++
.../phoenix/monitoring/OverAllQueryMetrics.java | 35 ++++++++++
.../phoenix/monitoring/PhoenixMetricsIT.java | 76 ++++++++++++++++++++++
.../monitoring/OverAllQueryMetricsTest.java | 24 +++++--
5 files changed, 154 insertions(+), 8 deletions(-)
diff --git
a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java
b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java
index a224a11156..a11560c6e3 100644
---
a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java
+++
b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java
@@ -124,6 +124,7 @@ import org.apache.phoenix.log.QueryLogger;
import org.apache.phoenix.log.QueryLoggerUtil;
import org.apache.phoenix.log.QueryStatus;
import org.apache.phoenix.monitoring.GlobalClientMetrics;
+import org.apache.phoenix.monitoring.OverAllQueryMetrics;
import org.apache.phoenix.monitoring.TableMetricsManager;
import org.apache.phoenix.optimize.Cost;
import org.apache.phoenix.parse.AddColumnStatement;
@@ -359,6 +360,7 @@ public class PhoenixStatement implements
PhoenixMonitoredStatement, SQLCloseable
clearResultSet();
PhoenixResultSet rs = null;
QueryPlan plan = null;
+ OverAllQueryMetrics overallQuerymetrics;
try {
PhoenixConnection conn = getConnection();
conn.checkOpen();
@@ -368,8 +370,15 @@ public class PhoenixStatement implements
PhoenixMonitoredStatement, SQLCloseable
&& stmt.getOperation() !=
Operation.UPGRADE) {
throw new UpgradeRequiredException();
}
+ final long queryPlanCreationStartTime =
+ EnvironmentEdgeManager.currentTimeMillis();
plan = stmt.compilePlan(PhoenixStatement.this,
Sequence.ValueOp.VALIDATE_SEQUENCE);
+ StatementContext context = plan.getContext();
+ overallQuerymetrics =
context.getOverallQueryMetrics();
+ overallQuerymetrics.setQueryCompilerTimeMS(
+ EnvironmentEdgeManager.currentTimeMillis()
+ - queryPlanCreationStartTime);
// Send mutations to hbase, so they are
visible to subsequent reads.
// Use original plan for data table so that
data and immutable indexes will be sent
// TODO: for joins, we need to iterate through
all tables, but we need the original table,
@@ -379,9 +388,14 @@ public class PhoenixStatement implements
PhoenixMonitoredStatement, SQLCloseable
}
Iterator<TableRef> tableRefs =
plan.getSourceRefs().iterator();
connection.getMutationState().sendUncommitted(tableRefs);
+ final long queryOptimizerStartTime =
+ EnvironmentEdgeManager.currentTimeMillis();
plan =
connection.getQueryServices().getOptimizer()
.optimize(PhoenixStatement.this, plan);
+ overallQuerymetrics.setQueryOptimizerTimeMS(
+ EnvironmentEdgeManager.currentTimeMillis()
+ - queryOptimizerStartTime);
setLastQueryPlan(plan);
//verify metadata for the table/view/index in
the query plan
@@ -399,15 +413,19 @@ public class PhoenixStatement implements
PhoenixMonitoredStatement, SQLCloseable
tableName =
plan.getTableRef().getTable().getPhysicalName()
.toString();
}
+ final long queryResultItrSetStartTime =
+ EnvironmentEdgeManager.currentTimeMillis();
// this will create its own trace internally,
so we don't wrap this
// whole thing in tracing
ResultIterator resultIterator =
plan.iterator();
+ overallQuerymetrics.setQueryResultItrTimeMS(
+ EnvironmentEdgeManager.currentTimeMillis()
+ - queryResultItrSetStartTime);
if (LOGGER.isDebugEnabled()) {
String explainPlan =
QueryUtil.getExplainPlan(resultIterator);
LOGGER.debug(LogUtil.addCustomAnnotations(
"Explain plan: " + explainPlan,
connection));
}
- StatementContext context = plan.getContext();
context.setQueryLogger(queryLogger);
if (queryLogger.isDebugEnabled()) {
queryLogger.log(QueryLogInfo.EXPLAIN_PLAN_I,
@@ -417,7 +435,7 @@ public class PhoenixStatement implements
PhoenixMonitoredStatement, SQLCloseable
context.getScan().toString() :
null);
}
- context.getOverallQueryMetrics().startQuery();
+ overallQuerymetrics.startQuery();
rs =
newResultSet(resultIterator,
plan.getProjector(),
plan.getContext());
diff --git
a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java
b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java
index 40b7932a28..b9e591c0e1 100644
---
a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java
+++
b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java
@@ -141,6 +141,11 @@ public enum MetricType {
CACHE_REFRESH_SPLITS_COUNTER("cr", "Number of times cache was refreshed
because of splits",LogLevel.DEBUG, PLong.INSTANCE),
WALL_CLOCK_TIME_MS("tq", "Wall clock time elapsed for the overall query
execution",LogLevel.INFO, PLong.INSTANCE),
RESULT_SET_TIME_MS("tn", "Wall clock time elapsed for reading all records
using resultSet.next()",LogLevel.INFO, PLong.INSTANCE),
+ QUERY_COMPILER_TIME_MS("qct", "Time elapsed in query compiler",
LogLevel.INFO, PLong.INSTANCE),
+ QUERY_OPTIMIZER_TIME_MS("qot", "Time elapsed in query optimizer",
+ LogLevel.INFO, PLong.INSTANCE),
+ QUERY_RESULT_ITR_TIME_MS("qrt", "Time elapsed in query result iterator",
+ LogLevel.INFO, PLong.INSTANCE),
OPEN_PHOENIX_CONNECTIONS_COUNTER("o", "Number of open phoenix
connections",LogLevel.OFF, PLong.INSTANCE),
OPEN_INTERNAL_PHOENIX_CONNECTIONS_COUNTER("io", "Number of open internal
phoenix connections",LogLevel.OFF, PLong.INSTANCE),
QUERY_SERVICES_COUNTER("cqs", "Number of ConnectionQueryServicesImpl
instantiated",LogLevel.OFF, PLong.INSTANCE),
diff --git
a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
index 5038cb3238..014ba0b4e1 100644
---
a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
+++
b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
@@ -19,9 +19,12 @@ package org.apache.phoenix.monitoring;
import static
org.apache.phoenix.monitoring.MetricType.CACHE_REFRESH_SPLITS_COUNTER;
import static org.apache.phoenix.monitoring.MetricType.NUM_PARALLEL_SCANS;
+import static org.apache.phoenix.monitoring.MetricType.QUERY_COMPILER_TIME_MS;
import static org.apache.phoenix.monitoring.MetricType.QUERY_FAILED_COUNTER;
+import static org.apache.phoenix.monitoring.MetricType.QUERY_OPTIMIZER_TIME_MS;
import static
org.apache.phoenix.monitoring.MetricType.QUERY_POINTLOOKUP_FAILED_COUNTER;
import static
org.apache.phoenix.monitoring.MetricType.QUERY_POINTLOOKUP_TIMEOUT_COUNTER;
+import static
org.apache.phoenix.monitoring.MetricType.QUERY_RESULT_ITR_TIME_MS;
import static
org.apache.phoenix.monitoring.MetricType.QUERY_SCAN_FAILED_COUNTER;
import static
org.apache.phoenix.monitoring.MetricType.QUERY_SCAN_TIMEOUT_COUNTER;
import static org.apache.phoenix.monitoring.MetricType.QUERY_TIMEOUT_COUNTER;
@@ -43,6 +46,9 @@ public class OverAllQueryMetrics {
private final CombinableMetric numParallelScans;
private final CombinableMetric wallClockTimeMS;
private final CombinableMetric resultSetTimeMS;
+ private final CombinableMetric queryCompilerTimeMS;
+ private final CombinableMetric queryOptimizerTimeMS;
+ private final CombinableMetric queryResultItrSetTimeMS;
private final CombinableMetric queryTimedOut;
private final CombinableMetric queryPointLookupTimedOut;
private final CombinableMetric queryScanTimedOut;
@@ -56,6 +62,12 @@ public class OverAllQueryMetrics {
WALL_CLOCK_TIME_MS);
resultSetWatch =
MetricUtil.getMetricsStopWatch(isRequestMetricsEnabled, connectionLogLevel,
RESULT_SET_TIME_MS);
+ queryCompilerTimeMS =
MetricUtil.getCombinableMetric(isRequestMetricsEnabled,
+ connectionLogLevel, QUERY_COMPILER_TIME_MS);
+ queryOptimizerTimeMS =
MetricUtil.getCombinableMetric(isRequestMetricsEnabled,
+ connectionLogLevel, QUERY_OPTIMIZER_TIME_MS);
+ queryResultItrSetTimeMS =
MetricUtil.getCombinableMetric(isRequestMetricsEnabled,
+ connectionLogLevel, QUERY_RESULT_ITR_TIME_MS);
numParallelScans =
MetricUtil.getCombinableMetric(isRequestMetricsEnabled,
connectionLogLevel, NUM_PARALLEL_SCANS);
wallClockTimeMS =
MetricUtil.getCombinableMetric(isRequestMetricsEnabled,
@@ -106,6 +118,18 @@ public class OverAllQueryMetrics {
cacheRefreshedDueToSplits.increment();
}
+ public void setQueryCompilerTimeMS(long time) {
+ queryCompilerTimeMS.set(time);
+ }
+
+ public void setQueryOptimizerTimeMS(long time) {
+ queryOptimizerTimeMS.set(time);
+ }
+
+ public void setQueryResultItrTimeMS(long time) {
+ queryResultItrSetTimeMS.set(time);
+ }
+
public void startQuery() {
if (!queryWatch.isRunning()) {
queryWatch.start();
@@ -147,6 +171,11 @@ public class OverAllQueryMetrics {
metricsForPublish.put(numParallelScans.getMetricType(),
numParallelScans.getValue());
metricsForPublish.put(wallClockTimeMS.getMetricType(),
wallClockTimeMS.getValue());
metricsForPublish.put(resultSetTimeMS.getMetricType(),
resultSetTimeMS.getValue());
+ metricsForPublish.put(queryCompilerTimeMS.getMetricType(),
queryCompilerTimeMS.getValue());
+ metricsForPublish.put(queryOptimizerTimeMS.getMetricType(),
+ queryOptimizerTimeMS.getValue());
+ metricsForPublish.put(queryResultItrSetTimeMS.getMetricType(),
+ queryResultItrSetTimeMS.getValue());
metricsForPublish.put(queryTimedOut.getMetricType(),
queryTimedOut.getValue());
metricsForPublish.put(queryPointLookupTimedOut.getMetricType(),
queryPointLookupTimedOut.getValue());
metricsForPublish.put(queryScanTimedOut.getMetricType(),
queryScanTimedOut.getValue());
@@ -161,6 +190,9 @@ public class OverAllQueryMetrics {
numParallelScans.reset();
wallClockTimeMS.reset();
resultSetTimeMS.reset();
+ queryCompilerTimeMS.reset();
+ queryOptimizerTimeMS.reset();
+ queryResultItrSetTimeMS.reset();
queryTimedOut.reset();
queryPointLookupTimedOut.reset();
queryScanTimedOut.reset();
@@ -183,6 +215,9 @@ public class OverAllQueryMetrics {
numParallelScans.combine(metric.numParallelScans);
wallClockTimeMS.combine(metric.wallClockTimeMS);
resultSetTimeMS.combine(metric.resultSetTimeMS);
+ queryCompilerTimeMS.combine(queryCompilerTimeMS);
+ queryOptimizerTimeMS.combine(queryOptimizerTimeMS);
+ queryResultItrSetTimeMS.combine(queryResultItrSetTimeMS);
return this;
}
diff --git
a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java
b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java
index ed0d319dea..d190a68cbf 100644
---
a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java
+++
b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java
@@ -43,6 +43,9 @@ import static
org.apache.phoenix.monitoring.MetricType.DELETE_COMMIT_TIME;
import static org.apache.phoenix.monitoring.MetricType.MEMORY_CHUNK_BYTES;
import static org.apache.phoenix.monitoring.MetricType.MUTATION_BATCH_COUNTER;
import static org.apache.phoenix.monitoring.MetricType.MUTATION_COMMIT_TIME;
+import static org.apache.phoenix.monitoring.MetricType.QUERY_COMPILER_TIME_MS;
+import static org.apache.phoenix.monitoring.MetricType.QUERY_OPTIMIZER_TIME_MS;
+import static
org.apache.phoenix.monitoring.MetricType.QUERY_RESULT_ITR_TIME_MS;
import static org.apache.phoenix.monitoring.MetricType.QUERY_TIMEOUT_COUNTER;
import static org.apache.phoenix.monitoring.MetricType.TASK_END_TO_END_TIME;
import static org.apache.phoenix.monitoring.MetricType.TASK_EXECUTED_COUNTER;
@@ -56,6 +59,7 @@ import static org.junit.Assert.assertTrue;
import static org.junit.Assert.fail;
import java.lang.reflect.Field;
+import java.math.BigDecimal;
import java.sql.Connection;
import java.sql.Date;
import java.sql.DriverManager;
@@ -494,6 +498,78 @@ public class PhoenixMetricsIT extends BasePhoenixMetricsIT
{
resultSetBeingTested, expectedTableNames);
}
+ @Test
+ public void testExecuteQuerySubMetricsForSelect() throws Exception {
+ String tableName = generateUniqueName();
+ String index1Name = generateUniqueName() + "_IDX1";
+ String index2Name = generateUniqueName() + "_IDX2";
+ String index3Name = generateUniqueName() + "_IDX3";
+ // Creating table with high salt bucket to increase ResultIterator time
+ long numSaltBuckets = 50;
+
+ try (Connection conn = DriverManager.getConnection(getUrl())) {
+ String ddl = "CREATE TABLE " + tableName + " (" +
+ "ID INTEGER NOT NULL PRIMARY KEY, " +
+ "CATEGORY VARCHAR(50), " +
+ "PRICE DECIMAL(12,2), " +
+ "QUANTITY INTEGER)" +
+ " SALT_BUCKETS = " + numSaltBuckets;
+ conn.createStatement().execute(ddl);
+
+ String idx1 = "CREATE INDEX " + index1Name + " ON " + tableName +
" (CATEGORY, PRICE)";
+ String idx2 = "CREATE INDEX " + index2Name + " ON " + tableName +
" (PRICE, QUANTITY)";
+ String idx3 = "CREATE INDEX " + index3Name + " ON " + tableName +
" (QUANTITY, CATEGORY)";
+ conn.createStatement().execute(idx1);
+ conn.createStatement().execute(idx2);
+ conn.createStatement().execute(idx3);
+
+ PreparedStatement stmt = conn.prepareStatement(
+ "UPSERT INTO " + tableName + " VALUES (?, ?, ?, ?)");
+
+ String[] categories = {"A", "B", "C", "D", "E"};
+
+ for (int i = 1; i <= 2000; i++) {
+ stmt.setInt(1, i);
+ stmt.setString(2, categories[i % categories.length]);
+ stmt.setBigDecimal(3, new BigDecimal(i/23));
+ stmt.setInt(4, (i % 200) + 1);
+ stmt.executeUpdate();
+ }
+ conn.commit();
+
+ String selectQuery =
+ "SELECT " +
+ " CATEGORY, " +
+ " COUNT(*) as total_count, " +
+ " AVG(PRICE) as avg_price, " +
+ " SUM(QUANTITY) as total_quantity " +
+ "FROM " + tableName + " " +
+ "WHERE " +
+ " CATEGORY IN (?, ?, ?, ?, ?) " +
+ "GROUP BY CATEGORY " +
+ "ORDER BY " +
+ " SUM(PRICE * QUANTITY) DESC";
+
+ PreparedStatement queryStmt = conn.prepareStatement(selectQuery);
+ queryStmt.setString(1, "A");
+ queryStmt.setString(2, "B");
+ queryStmt.setString(3, "C");
+ queryStmt.setString(4, "D");
+ queryStmt.setString(5, "E");
+
+ ResultSet rs = queryStmt.executeQuery();
+ PhoenixResultSet phoenixResultSet =
rs.unwrap(PhoenixResultSet.class);
+ Map<MetricType, Long> overallReadMetrics =
PhoenixRuntime.getOverAllReadRequestMetricInfo(rs);
+
+ assertTrue("Query compiler time should have been greater than
zero",
+ overallReadMetrics.get(QUERY_COMPILER_TIME_MS) > 0);
+ assertTrue("Query optimizer time should have been greater than
zero",
+ overallReadMetrics.get(QUERY_OPTIMIZER_TIME_MS) > 0);
+ assertTrue("Query Result Itr time should have been greater than
zero",
+ overallReadMetrics.get(QUERY_RESULT_ITR_TIME_MS) > 0);
+ }
+ }
+
@Test
public void testMetricsForUpsert() throws Exception {
String tableName = generateUniqueName();
diff --git
a/phoenix-core/src/test/java/org/apache/phoenix/monitoring/OverAllQueryMetricsTest.java
b/phoenix-core/src/test/java/org/apache/phoenix/monitoring/OverAllQueryMetricsTest.java
index f97731d3e3..f8a3b8c201 100644
---
a/phoenix-core/src/test/java/org/apache/phoenix/monitoring/OverAllQueryMetricsTest.java
+++
b/phoenix-core/src/test/java/org/apache/phoenix/monitoring/OverAllQueryMetricsTest.java
@@ -29,7 +29,10 @@ import java.util.Map;
import static
org.apache.phoenix.monitoring.MetricType.CACHE_REFRESH_SPLITS_COUNTER;
import static org.apache.phoenix.monitoring.MetricType.NO_OP_METRIC;
import static org.apache.phoenix.monitoring.MetricType.NUM_PARALLEL_SCANS;
+import static org.apache.phoenix.monitoring.MetricType.QUERY_COMPILER_TIME_MS;
import static org.apache.phoenix.monitoring.MetricType.QUERY_FAILED_COUNTER;
+import static org.apache.phoenix.monitoring.MetricType.QUERY_OPTIMIZER_TIME_MS;
+import static
org.apache.phoenix.monitoring.MetricType.QUERY_RESULT_ITR_TIME_MS;
import static org.apache.phoenix.monitoring.MetricType.QUERY_TIMEOUT_COUNTER;
import static org.apache.phoenix.monitoring.MetricType.RESULT_SET_TIME_MS;
import static org.apache.phoenix.monitoring.MetricType.WALL_CLOCK_TIME_MS;
@@ -105,20 +108,20 @@ public class OverAllQueryMetricsTest {
overAllQueryMetrics.startQuery();
overAllQueryMetrics.startResultSetWatch();
assertPublishedMetrics(overAllQueryMetrics.publish(),
numParallelScans, queryTimeouts,
- queryFailures, cacheRefreshesDueToSplits, 0L);
+ queryFailures, cacheRefreshesDueToSplits, 0L, delta, delta,
delta);
overAllQueryMetrics.endQuery();
overAllQueryMetrics.stopResultSetWatch();
// expect 2 * delta since we call both endQuery() and
stopResultSetWatch()
assertPublishedMetrics(overAllQueryMetrics.publish(),
numParallelScans, queryTimeouts,
- queryFailures, cacheRefreshesDueToSplits, 2*delta);
+ queryFailures, cacheRefreshesDueToSplits, 2*delta, delta,
delta, delta);
}
@Test
public void testReset() {
assertPublishedMetrics(overAllQueryMetrics.publish(),
numParallelScans, queryTimeouts,
- queryFailures, cacheRefreshesDueToSplits, 0L);
+ queryFailures, cacheRefreshesDueToSplits, 0L, delta, delta,
delta);
overAllQueryMetrics.reset();
- assertPublishedMetrics(overAllQueryMetrics.publish(), 0L, 0L, 0L, 0L,
0L);
+ assertPublishedMetrics(overAllQueryMetrics.publish(), 0L, 0L, 0L, 0L,
0L, 0L, 0L, 0L);
}
@Test
@@ -133,7 +136,7 @@ public class OverAllQueryMetricsTest {
OverAllQueryMetrics finalMetricObj =
this.overAllQueryMetrics.combine(otherMetrics);
assertPublishedMetrics(finalMetricObj.publish(), numParallelScans +
otherNumParallelScans,
queryTimeouts + otherQueryTimeouts, queryFailures +
otherQueryFailures,
- cacheRefreshesDueToSplits + otherCacheRefreshes, 0L);
+ cacheRefreshesDueToSplits + otherCacheRefreshes, 0L, 2*delta,
2*delta, 2*delta);
}
@Test
@@ -159,6 +162,9 @@ public class OverAllQueryMetricsTest {
for (int i = 0; i < cacheRefreshesDueToSplitsSetting; i++) {
metricsObj.cacheRefreshedDueToSplits();
}
+ metricsObj.setQueryCompilerTimeMS(delta);
+ metricsObj.setQueryOptimizerTimeMS(delta);
+ metricsObj.setQueryResultItrTimeMS(delta);
}
private void assertPublishedMetrics(
@@ -167,13 +173,19 @@ public class OverAllQueryMetricsTest {
final long expectedQueryTimeouts,
final long expectedQueryFailures,
final long expectedCacheRefreshes,
- final long expectedElapsedTime) {
+ final long expectedElapsedTime,
+ final long expectedQueryCompilerTimeMS,
+ final long expectedQueryOptimizerTimeMS,
+ final long expectedQueryResultItrSetTimeMS) {
assertEquals(expectedNumParallelScans,
(long)metrics.get(NUM_PARALLEL_SCANS));
assertEquals(expectedQueryTimeouts,
(long)metrics.get(QUERY_TIMEOUT_COUNTER));
assertEquals(expectedQueryFailures,
(long)metrics.get(QUERY_FAILED_COUNTER));
assertEquals(expectedCacheRefreshes,
(long)metrics.get(CACHE_REFRESH_SPLITS_COUNTER));
assertEquals(expectedElapsedTime,
(long)metrics.get(WALL_CLOCK_TIME_MS));
assertEquals(expectedElapsedTime,
(long)metrics.get(RESULT_SET_TIME_MS));
+ assertEquals(expectedQueryCompilerTimeMS,
(long)metrics.get(QUERY_COMPILER_TIME_MS));
+ assertEquals(expectedQueryOptimizerTimeMS,
(long)metrics.get(QUERY_OPTIMIZER_TIME_MS));
+ assertEquals(expectedQueryResultItrSetTimeMS,
(long)metrics.get(QUERY_RESULT_ITR_TIME_MS));
}
}
