From df6acd1e5751f17800485c3edb1ac96f15dd2253 Mon Sep 17 00:00:00 2001 From: Rahul Kumar Date: Wed, 26 Feb 2025 13:09:21 +0530 Subject: [PATCH 1/6] [PHOENIX-7535] Capture time spent in various stages of exceuteQuery call --- .../apache/phoenix/jdbc/PhoenixStatement.java | 16 ++++++- .../apache/phoenix/monitoring/MetricType.java | 3 ++ .../monitoring/OverAllQueryMetrics.java | 44 ++++++++++++++----- .../phoenix/monitoring/PhoenixMetricsIT.java | 17 +++---- .../monitoring/OverAllQueryMetricsTest.java | 32 ++++++++------ 5 files changed, 75 insertions(+), 37 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 8c0e5cafe9f..0e81cd26de3 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.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; @@ -367,6 +368,10 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, clearResultSet(); PhoenixResultSet rs = null; QueryPlan plan = null; + long queryPlanCreationTime = 0; + long queryOptimizerTime = 0; + long queryResultSetTime = 0; + OverAllQueryMetrics overallQuerymetrics; try { PhoenixConnection conn = getConnection(); conn.checkOpen(); @@ -376,8 +381,12 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, && stmt.getOperation() != Operation.UPGRADE) { throw new UpgradeRequiredException(); } + final long queryPlanCreationStartTime = System.nanoTime(); plan = stmt.compilePlan(PhoenixStatement.this, Sequence.ValueOp.VALIDATE_SEQUENCE); + StatementContext context = plan.getContext(); + overallQuerymetrics = context.getOverallQueryMetrics(); + overallQuerymetrics.setQueryCompilerTimeNS(System.nanoTime() - 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, @@ -387,9 +396,11 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, } Iterator tableRefs = plan.getSourceRefs().iterator(); connection.getMutationState().sendUncommitted(tableRefs); + final long queryOptimizerStartTime = System.nanoTime(); plan = connection.getQueryServices().getOptimizer() .optimize(PhoenixStatement.this, plan); + overallQuerymetrics.setQueryOptimizerTimeNS(System.nanoTime() - queryOptimizerStartTime); setLastQueryPlan(plan); //verify metadata for the table/view/index in the query plan @@ -407,6 +418,7 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, tableName = plan.getTableRef().getTable().getPhysicalName() .toString(); } + final long queryResultItrSetStartTime = System.nanoTime(); // this will create its own trace internally, so we don't wrap this // whole thing in tracing ResultIterator resultIterator = plan.iterator(); @@ -415,7 +427,6 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, LOGGER.debug(LogUtil.addCustomAnnotations( "Explain plan: " + explainPlan, connection)); } - StatementContext context = plan.getContext(); context.setQueryLogger(queryLogger); if (queryLogger.isDebugEnabled()) { queryLogger.log(QueryLogInfo.EXPLAIN_PLAN_I, @@ -425,10 +436,11 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, context.getScan().toString() : null); } - context.getOverallQueryMetrics().startQuery(); + overallQuerymetrics.startQuery(); rs = newResultSet(resultIterator, plan.getProjector(), plan.getContext()); + overallQuerymetrics.setQueryResultItrSetTimeNs(System.nanoTime() - queryResultItrSetStartTime); // newResultset sets lastResultset setLastQueryPlan(plan); setLastUpdateCount(NO_UPDATE); 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 d66fb0e19df..3eb2eb2cd8e 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 @@ -138,6 +138,9 @@ 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_NS("qct","Time in nanoseconds elapsed in query compiler", LogLevel.INFO, PLong.INSTANCE), + QUERY_OPTIMIZER_TIME_NS("qot","Time in nanoseconds elapsed in query optimizer", LogLevel.INFO, PLong.INSTANCE), + QUERY_RESULT_ITR_SET_TIME_NS("qrt","Time in nanoseconds elapsed in query result iterator and set", 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 5038cb32387..f8a4b3a1ed5 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 @@ -17,23 +17,14 @@ */ 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_FAILED_COUNTER; -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_SCAN_FAILED_COUNTER; -import static org.apache.phoenix.monitoring.MetricType.QUERY_SCAN_TIMEOUT_COUNTER; -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; - import java.util.HashMap; import java.util.Map; import org.apache.phoenix.log.LogLevel; import org.apache.phoenix.thirdparty.com.google.common.annotations.VisibleForTesting; +import static org.apache.phoenix.monitoring.MetricType.*; + /** * Class that represents the overall metrics associated with a query being executed by the phoenix. */ @@ -43,6 +34,9 @@ public class OverAllQueryMetrics { private final CombinableMetric numParallelScans; private final CombinableMetric wallClockTimeMS; private final CombinableMetric resultSetTimeMS; + private final CombinableMetric queryCompilerTimeNS; + private final CombinableMetric queryOptimizerTimeNS; + private final CombinableMetric queryResultItrSetTimeNs; private final CombinableMetric queryTimedOut; private final CombinableMetric queryPointLookupTimedOut; private final CombinableMetric queryScanTimedOut; @@ -56,6 +50,12 @@ public OverAllQueryMetrics(boolean isRequestMetricsEnabled, LogLevel connectionL WALL_CLOCK_TIME_MS); resultSetWatch = MetricUtil.getMetricsStopWatch(isRequestMetricsEnabled, connectionLogLevel, RESULT_SET_TIME_MS); + queryCompilerTimeNS = MetricUtil.getCombinableMetric(isRequestMetricsEnabled, + connectionLogLevel, QUERY_COMPILER_TIME_NS); + queryOptimizerTimeNS = MetricUtil.getCombinableMetric(isRequestMetricsEnabled, + connectionLogLevel, QUERY_OPTIMIZER_TIME_NS); + queryResultItrSetTimeNs = MetricUtil.getCombinableMetric(isRequestMetricsEnabled, + connectionLogLevel, QUERY_RESULT_ITR_SET_TIME_NS); numParallelScans = MetricUtil.getCombinableMetric(isRequestMetricsEnabled, connectionLogLevel, NUM_PARALLEL_SCANS); wallClockTimeMS = MetricUtil.getCombinableMetric(isRequestMetricsEnabled, @@ -106,6 +106,18 @@ public void cacheRefreshedDueToSplits() { cacheRefreshedDueToSplits.increment(); } + public void setQueryCompilerTimeNS(long timeNS) { + queryCompilerTimeNS.set(timeNS); + } + + public void setQueryOptimizerTimeNS(long timeNS) { + queryOptimizerTimeNS.set(timeNS); + } + + public void setQueryResultItrSetTimeNs(long timeNS) { + queryResultItrSetTimeNs.set(timeNS); + } + public void startQuery() { if (!queryWatch.isRunning()) { queryWatch.start(); @@ -147,6 +159,9 @@ public Map publish() { metricsForPublish.put(numParallelScans.getMetricType(), numParallelScans.getValue()); metricsForPublish.put(wallClockTimeMS.getMetricType(), wallClockTimeMS.getValue()); metricsForPublish.put(resultSetTimeMS.getMetricType(), resultSetTimeMS.getValue()); + metricsForPublish.put(queryCompilerTimeNS.getMetricType(), queryCompilerTimeNS.getValue()); + metricsForPublish.put(queryOptimizerTimeNS.getMetricType(), queryOptimizerTimeNS.getValue()); + metricsForPublish.put(queryResultItrSetTimeNs.getMetricType(), queryResultItrSetTimeNs.getValue()); metricsForPublish.put(queryTimedOut.getMetricType(), queryTimedOut.getValue()); metricsForPublish.put(queryPointLookupTimedOut.getMetricType(), queryPointLookupTimedOut.getValue()); metricsForPublish.put(queryScanTimedOut.getMetricType(), queryScanTimedOut.getValue()); @@ -170,6 +185,10 @@ public void reset() { cacheRefreshedDueToSplits.reset(); queryWatch.stop(); resultSetWatch.stop(); + queryCompilerTimeNS.reset(); + queryOptimizerTimeNS.reset(); + queryResultItrSetTimeNs.reset(); + } public OverAllQueryMetrics combine(OverAllQueryMetrics metric) { @@ -183,6 +202,9 @@ public OverAllQueryMetrics combine(OverAllQueryMetrics metric) { numParallelScans.combine(metric.numParallelScans); wallClockTimeMS.combine(metric.wallClockTimeMS); resultSetTimeMS.combine(metric.resultSetTimeMS); + queryCompilerTimeNS.combine(queryCompilerTimeNS); + queryOptimizerTimeNS.combine(queryOptimizerTimeNS); + queryResultItrSetTimeNs.combine(queryResultItrSetTimeNs); 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 8c007df082f..fa35fa21bc8 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 @@ -38,16 +38,7 @@ import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_SPOOL_FILE_COUNTER; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_TASK_END_TO_END_TIME; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_TASK_EXECUTION_TIME; -import static org.apache.phoenix.monitoring.MetricType.COUNT_MILLS_BETWEEN_NEXTS; -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_COMMIT_TIME; -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; -import static org.apache.phoenix.monitoring.MetricType.TASK_EXECUTION_TIME; -import static org.apache.phoenix.monitoring.MetricType.TASK_QUEUE_WAIT_TIME; -import static org.apache.phoenix.monitoring.MetricType.UPSERT_COMMIT_TIME; +import static org.apache.phoenix.monitoring.MetricType.*; import static org.apache.phoenix.util.PhoenixRuntime.TENANT_ID_ATTRIB; import static org.apache.phoenix.util.PhoenixRuntime.UPSERT_BATCH_SIZE_ATTRIB; import static org.junit.Assert.assertEquals; @@ -944,8 +935,12 @@ private void changeInternalStateForTesting(PhoenixResultSet rs) throws NoSuchFie } private void assertReadMetricValuesForSelectSql(ArrayList numRows, ArrayList numExpectedTasks, - PhoenixResultSet resultSetBeingTested, Set expectedTableNames) throws SQLException { + PhoenixResultSet resultSetBeingTested, Set expectedTableNames) throws Exception { Map> metrics = PhoenixRuntime.getRequestReadMetricInfo(resultSetBeingTested); + Map overallReadMetrics = PhoenixRuntime.getOverAllReadRequestMetricInfo(resultSetBeingTested); + assertTrue("Query compiler time should be greater than zero", overallReadMetrics.get(QUERY_COMPILER_TIME_NS) > 0); + assertTrue("Query optimizer time should be greater than zero", overallReadMetrics.get(QUERY_OPTIMIZER_TIME_NS) > 0); + assertTrue("Query Result Itr time should be greater than zero", overallReadMetrics.get(QUERY_RESULT_ITR_SET_TIME_NS) > 0); int counter = 0; for (Entry> entry : metrics.entrySet()) { String tableName = entry.getKey(); 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 f97731d3e38..d4507a46f58 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 @@ -26,13 +26,7 @@ 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_FAILED_COUNTER; -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; +import static org.apache.phoenix.monitoring.MetricType.*; import static org.junit.Assert.assertEquals; public class OverAllQueryMetricsTest { @@ -42,6 +36,7 @@ public class OverAllQueryMetricsTest { private static final long delta = 1000L; private static final int queryTimeouts = 5; private static final int queryFailures = 8; + private static final long queryCompilerTimeNs = 25000; private static final int cacheRefreshesDueToSplits = 15; @Before @@ -105,20 +100,20 @@ public void testPublish() { 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 +128,7 @@ public void testCombine() { 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 +154,10 @@ private void populateMetrics(OverAllQueryMetrics metricsObj, long numParallelSca for (int i = 0; i < cacheRefreshesDueToSplitsSetting; i++) { metricsObj.cacheRefreshedDueToSplits(); } + metricsObj.setQueryCompilerTimeNS(delta); + metricsObj.setQueryOptimizerTimeNS(delta); + metricsObj.setQueryResultItrSetTimeNs(delta); + } private void assertPublishedMetrics( @@ -167,13 +166,20 @@ private void assertPublishedMetrics( final long expectedQueryTimeouts, final long expectedQueryFailures, final long expectedCacheRefreshes, - final long expectedElapsedTime) { + final long expectedElapsedTime, + final long expectedQueryCompilerTimeNs, + final long expectedQueryOptimizerTimeNs, + final long expectedQueryResultItrSetTimeNs) { 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(expectedQueryCompilerTimeNs, (long)metrics.get(QUERY_COMPILER_TIME_NS)); + assertEquals(expectedQueryOptimizerTimeNs, (long)metrics.get(QUERY_OPTIMIZER_TIME_NS)); + assertEquals(expectedQueryResultItrSetTimeNs, (long)metrics.get(QUERY_RESULT_ITR_SET_TIME_NS)); + } } From 4e0ec25d7eaffb535a1f79cd5b634c2e46146ce5 Mon Sep 17 00:00:00 2001 From: Rahul Kumar Date: Wed, 26 Feb 2025 13:12:04 +0530 Subject: [PATCH 2/6] [PHOENIX-7535] Capture time spent in various stages of exceuteQuery call --- .../phoenix/monitoring/PhoenixMetricsIT.java | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) 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 fa35fa21bc8..80b05ad3d01 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 @@ -38,7 +38,19 @@ import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_SPOOL_FILE_COUNTER; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_TASK_END_TO_END_TIME; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_TASK_EXECUTION_TIME; -import static org.apache.phoenix.monitoring.MetricType.*; +import static org.apache.phoenix.monitoring.MetricType.COUNT_MILLS_BETWEEN_NEXTS; +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_COMMIT_TIME; +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; +import static org.apache.phoenix.monitoring.MetricType.TASK_EXECUTION_TIME; +import static org.apache.phoenix.monitoring.MetricType.TASK_QUEUE_WAIT_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_COMMIT_TIME; +import static org.apache.phoenix.monitoring.MetricType.QUERY_COMPILER_TIME_NS; +import static org.apache.phoenix.monitoring.MetricType.QUERY_OPTIMIZER_TIME_NS; +import static org.apache.phoenix.monitoring.MetricType.QUERY_RESULT_ITR_SET_TIME_NS; import static org.apache.phoenix.util.PhoenixRuntime.TENANT_ID_ATTRIB; import static org.apache.phoenix.util.PhoenixRuntime.UPSERT_BATCH_SIZE_ATTRIB; import static org.junit.Assert.assertEquals; From d1420223794c4a893a5989076884c4c3dcfdf8f4 Mon Sep 17 00:00:00 2001 From: Rahul Kumar Date: Wed, 26 Feb 2025 13:14:20 +0530 Subject: [PATCH 3/6] [PHOENIX-7535] Capture time spent in various stages of exceuteQuery call --- .../phoenix/monitoring/OverAllQueryMetrics.java | 1 - .../phoenix/monitoring/OverAllQueryMetricsTest.java | 12 ++++++++++-- 2 files changed, 10 insertions(+), 3 deletions(-) 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 f8a4b3a1ed5..3f14b52128c 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 @@ -188,7 +188,6 @@ public void reset() { queryCompilerTimeNS.reset(); queryOptimizerTimeNS.reset(); queryResultItrSetTimeNs.reset(); - } public OverAllQueryMetrics combine(OverAllQueryMetrics metric) { 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 d4507a46f58..42e6c505b64 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 @@ -26,7 +26,16 @@ import java.util.Map; -import static org.apache.phoenix.monitoring.MetricType.*; +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_FAILED_COUNTER; +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; +import static org.apache.phoenix.monitoring.MetricType.QUERY_COMPILER_TIME_NS; +import static org.apache.phoenix.monitoring.MetricType.QUERY_OPTIMIZER_TIME_NS; +import static org.apache.phoenix.monitoring.MetricType.QUERY_RESULT_ITR_SET_TIME_NS; import static org.junit.Assert.assertEquals; public class OverAllQueryMetricsTest { @@ -36,7 +45,6 @@ public class OverAllQueryMetricsTest { private static final long delta = 1000L; private static final int queryTimeouts = 5; private static final int queryFailures = 8; - private static final long queryCompilerTimeNs = 25000; private static final int cacheRefreshesDueToSplits = 15; @Before From 11fb0e4cc04d95a21362a33af895dd97987dbfca Mon Sep 17 00:00:00 2001 From: Rahul Kumar Date: Wed, 26 Feb 2025 13:17:06 +0530 Subject: [PATCH 4/6] [PHOENIX-7535] Capture time spent in various stages of exceuteQuery call --- .../org/apache/phoenix/monitoring/OverAllQueryMetricsTest.java | 2 -- 1 file changed, 2 deletions(-) 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 42e6c505b64..457fd405d8c 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 @@ -165,7 +165,6 @@ private void populateMetrics(OverAllQueryMetrics metricsObj, long numParallelSca metricsObj.setQueryCompilerTimeNS(delta); metricsObj.setQueryOptimizerTimeNS(delta); metricsObj.setQueryResultItrSetTimeNs(delta); - } private void assertPublishedMetrics( @@ -187,7 +186,6 @@ private void assertPublishedMetrics( assertEquals(expectedQueryCompilerTimeNs, (long)metrics.get(QUERY_COMPILER_TIME_NS)); assertEquals(expectedQueryOptimizerTimeNs, (long)metrics.get(QUERY_OPTIMIZER_TIME_NS)); assertEquals(expectedQueryResultItrSetTimeNs, (long)metrics.get(QUERY_RESULT_ITR_SET_TIME_NS)); - } } From 394c9e09f199d48c9b026cd3b2b952496c7397d5 Mon Sep 17 00:00:00 2001 From: Rahul Kumar Date: Wed, 26 Feb 2025 16:17:39 +0530 Subject: [PATCH 5/6] [PHOENIX-7535] Capture time spent in various stages of exceuteQuery call --- .../phoenix/monitoring/OverAllQueryMetrics.java | 16 ++++++++++++++-- 1 file changed, 14 insertions(+), 2 deletions(-) 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 3f14b52128c..b6a6bea8ec8 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 @@ -17,14 +17,26 @@ */ 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_FAILED_COUNTER; +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_SCAN_FAILED_COUNTER; +import static org.apache.phoenix.monitoring.MetricType.QUERY_SCAN_TIMEOUT_COUNTER; +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; +import static org.apache.phoenix.monitoring.MetricType.QUERY_COMPILER_TIME_NS; +import static org.apache.phoenix.monitoring.MetricType.QUERY_OPTIMIZER_TIME_NS; +import static org.apache.phoenix.monitoring.MetricType.QUERY_RESULT_ITR_SET_TIME_NS; + import java.util.HashMap; import java.util.Map; import org.apache.phoenix.log.LogLevel; import org.apache.phoenix.thirdparty.com.google.common.annotations.VisibleForTesting; -import static org.apache.phoenix.monitoring.MetricType.*; - /** * Class that represents the overall metrics associated with a query being executed by the phoenix. */ From 01c63682f3067f33b976f531af832fbcfdeafb78 Mon Sep 17 00:00:00 2001 From: Rahul Kumar Date: Wed, 26 Feb 2025 16:19:31 +0530 Subject: [PATCH 6/6] [PHOENIX-7535] Capture time spent in various stages of exceuteQuery call --- .../main/java/org/apache/phoenix/jdbc/PhoenixStatement.java | 3 --- 1 file changed, 3 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 0e81cd26de3..7b45d3e4dac 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 @@ -368,9 +368,6 @@ private PhoenixResultSet executeQuery(final CompilableStatement stmt, clearResultSet(); PhoenixResultSet rs = null; QueryPlan plan = null; - long queryPlanCreationTime = 0; - long queryOptimizerTime = 0; - long queryResultSetTime = 0; OverAllQueryMetrics overallQuerymetrics; try { PhoenixConnection conn = getConnection();