This is an automated email from the ASF dual-hosted git repository. vjasani 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 6e1812082b PHOENIX-7625 Adding query plan information to ConnectionActivityLogger (#2246) 6e1812082b is described below commit 6e1812082b410848d081b22dcbb28bf2f3c15a71 Author: vikas meka <vm...@salesforce.com> AuthorDate: Tue Jul 29 15:00:03 2025 -0700 PHOENIX-7625 Adding query plan information to ConnectionActivityLogger (#2246) --- .../org/apache/phoenix/jdbc/PhoenixStatement.java | 46 ++++++++++++++++++++ .../org/apache/phoenix/log/ActivityLogInfo.java | 3 +- .../phoenix/log/ConnectionActivityLogger.java | 9 ++++ .../org/apache/phoenix/query/QueryServices.java | 2 + .../apache/phoenix/query/QueryServicesOptions.java | 4 ++ .../java/org/apache/phoenix/util/QueryUtil.java | 2 + .../org/apache/phoenix/end2end/ConnectionIT.java | 34 +++++++++++++++ .../phoenix/jdbc/LoggingConnectionLimiterIT.java | 50 ++++++++++++++++++++++ .../jdbc/LoggingSingleConnectionLimiterIT.java | 2 + 9 files changed, 151 insertions(+), 1 deletion(-) 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 4e4a34ae29..c0cb8a7339 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 @@ -43,6 +43,7 @@ import static org.apache.phoenix.monitoring.MetricType.UPSERT_FAILED_SQL_COUNTER import static org.apache.phoenix.monitoring.MetricType.UPSERT_SQL_COUNTER; import static org.apache.phoenix.monitoring.MetricType.UPSERT_SQL_QUERY_TIME; import static org.apache.phoenix.monitoring.MetricType.UPSERT_SUCCESS_SQL_COUNTER; +import static org.apache.phoenix.query.QueryServices.CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED; import java.io.File; import java.io.IOException; @@ -65,11 +66,14 @@ import java.util.List; import java.util.Map; import java.util.Properties; import java.util.Set; +import java.util.stream.Collectors; +import java.util.stream.Stream; import org.apache.hadoop.conf.Configuration; import org.apache.hadoop.fs.FileSystem; import org.apache.hadoop.fs.Path; import org.apache.hadoop.hbase.Cell; import org.apache.hadoop.hbase.CellComparator; +import org.apache.hadoop.hbase.HRegionLocation; import org.apache.hadoop.hbase.client.Consistency; import org.apache.hadoop.hbase.client.Result; import org.apache.hadoop.hbase.client.Scan; @@ -87,6 +91,7 @@ import org.apache.phoenix.compile.DeclareCursorCompiler; import org.apache.phoenix.compile.DeleteCompiler; import org.apache.phoenix.compile.DropSequenceCompiler; import org.apache.phoenix.compile.ExplainPlan; +import org.apache.phoenix.compile.ExplainPlanAttributes; import org.apache.phoenix.compile.ExpressionProjector; import org.apache.phoenix.compile.GroupByCompiler.GroupBy; import org.apache.phoenix.compile.ListJarsQueryPlan; @@ -292,6 +297,7 @@ public class PhoenixStatement implements PhoenixMonitoredStatement, SQLCloseable private int maxRows; private int fetchSize = -1; private int queryTimeoutMillis; + private boolean explainPlanLoggingEnabled; // Caching per Statement protected final Calendar localCalendar = Calendar.getInstance(); private boolean validateLastDdlTimestamp; @@ -302,6 +308,9 @@ public class PhoenixStatement implements PhoenixMonitoredStatement, SQLCloseable this.queryTimeoutMillis = getDefaultQueryTimeoutMillis(); this.validateLastDdlTimestamp = ValidateLastDDLTimestampUtil.getValidateLastDdlTimestampEnabled(this.connection); + this.explainPlanLoggingEnabled = + connection.getQueryServices().getProps().getBoolean(CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED, + QueryServicesOptions.DEFAULT_CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED); } /** @@ -417,6 +426,9 @@ public class PhoenixStatement implements PhoenixMonitoredStatement, SQLCloseable LOGGER .debug(LogUtil.addCustomAnnotations("Explain plan: " + explainPlan, connection)); } + if (explainPlanLoggingEnabled) { + updateExplainPlanInformation(plan); + } context.setQueryLogger(queryLogger); if (queryLogger.isDebugEnabled()) { queryLogger.log(QueryLogInfo.EXPLAIN_PLAN_I, @@ -2999,4 +3011,38 @@ public class PhoenixStatement implements PhoenixMonitoredStatement, SQLCloseable return localCalendar; } + private void updateExplainPlanInformation(QueryPlan plan) throws SQLException { + if ( + plan == null || !getConnection().getActivityLogger() + .isLevelEnabled(ActivityLogInfo.EXPLAIN_PLAN.getLogLevel()) + ) { + return; + } + + ExplainPlan explainPlan = plan.getExplainPlan(); + ExplainPlanAttributes explainPlanAttributes = explainPlan.getPlanStepsAsAttributes(); + + List<HRegionLocation> location = explainPlanAttributes.getRegionLocations(); + String regionInfo = getRegionInfo(location); + + String sb = Stream.of(explainPlanAttributes.getExplainScanType(), regionInfo) + .collect(Collectors.joining(",")); + updateActivityOnConnection(ActivityLogInfo.EXPLAIN_PLAN, sb); + } + + private String getRegionInfo(List<HRegionLocation> location) { + if (location == null || location.isEmpty()) { + return ""; + } + + String regions = + location.stream().map(regionLocation -> regionLocation.getRegion().getEncodedName()) + .collect(Collectors.joining(",")); + + String hostnames = + location.stream().map(HRegionLocation::getHostname).collect(Collectors.joining(",")); + + return QueryUtil.REGIONS + "={" + regions + "}," + QueryUtil.HOSTNAMES + "={" + hostnames + "}"; + } + } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/log/ActivityLogInfo.java b/phoenix-core-client/src/main/java/org/apache/phoenix/log/ActivityLogInfo.java index 9ad6f9e80a..3fff30b41b 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/log/ActivityLogInfo.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/log/ActivityLogInfo.java @@ -31,7 +31,8 @@ public enum ActivityLogInfo { REQUEST_ID("r", LogLevel.INFO, PVarchar.INSTANCE), TABLE_NAME("n", LogLevel.INFO, PVarchar.INSTANCE), OP_NAME("o", LogLevel.INFO, PVarchar.INSTANCE), - OP_STMTS("#", LogLevel.INFO, PInteger.INSTANCE); + OP_STMTS("#", LogLevel.INFO, PInteger.INSTANCE), + EXPLAIN_PLAN("ep", LogLevel.INFO, PVarchar.INSTANCE); public final String shortName; public final LogLevel logLevel; diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/log/ConnectionActivityLogger.java b/phoenix-core-client/src/main/java/org/apache/phoenix/log/ConnectionActivityLogger.java index 211a129234..8d1eae9f98 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/log/ConnectionActivityLogger.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/log/ConnectionActivityLogger.java @@ -154,4 +154,13 @@ public class ConnectionActivityLogger { ? logLevel.ordinal() <= this.logLevel.ordinal() : false; } + + /** + * Get the Explain plan information. + */ + public String getExplainPlanInfo() { + return isLevelEnabled(ActivityLogInfo.EXPLAIN_PLAN.getLogLevel()) + ? activityList.get(ActivityLogInfo.EXPLAIN_PLAN.ordinal()) + : null; + } } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServices.java b/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServices.java index 60efb91310..94f8574361 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServices.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServices.java @@ -347,6 +347,8 @@ public interface QueryServices extends SQLCloseable { "phoenix.internal.connection.max.allowed.connections"; public static final String CONNECTION_ACTIVITY_LOGGING_ENABLED = "phoenix.connection.activity.logging.enabled"; + String CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED = + "phoenix.connection.activity.logging.explain.plan.enabled"; public static final String CONNECTION_ACTIVITY_LOGGING_INTERVAL = "phoenix.connection.activity.logging.interval"; public static final String DEFAULT_COLUMN_ENCODED_BYTES_ATRRIB = diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServicesOptions.java b/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServicesOptions.java index 18da8b2ddd..16c1c28709 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServicesOptions.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/query/QueryServicesOptions.java @@ -33,6 +33,7 @@ import static org.apache.phoenix.query.QueryServices.COLLECT_REQUEST_LEVEL_METRI import static org.apache.phoenix.query.QueryServices.COMMIT_STATS_ASYNC; import static org.apache.phoenix.query.QueryServices.CONNECTION_ACTIVITY_LOGGING_ENABLED; import static org.apache.phoenix.query.QueryServices.CONNECTION_ACTIVITY_LOGGING_INTERVAL; +import static org.apache.phoenix.query.QueryServices.CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED; import static org.apache.phoenix.query.QueryServices.CONNECTION_QUERY_SERVICE_HISTOGRAM_SIZE_RANGES; import static org.apache.phoenix.query.QueryServices.CONNECTION_QUERY_SERVICE_METRICS_ENABLED; import static org.apache.phoenix.query.QueryServices.CONNECTION_QUERY_SERVICE_METRICS_PUBLISHER_CLASSNAME; @@ -388,6 +389,7 @@ public class QueryServicesOptions { public static final int DEFAULT_INTERNAL_CONNECTION_MAX_ALLOWED_CONNECTIONS = 0; public static final boolean DEFAULT_CONNECTION_ACTIVITY_LOGGING_ENABLED = false; + public static final boolean DEFAULT_CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED = false; public static final int DEFAULT_CONNECTION_ACTIVITY_LOGGING_INTERVAL_IN_MINS = 15; public static final boolean DEFAULT_STATS_COLLECTION_ENABLED = true; public static final boolean DEFAULT_USE_STATS_FOR_PARALLELIZATION = true; @@ -597,6 +599,8 @@ public class QueryServicesOptions { .setIfUnset(SERVER_MERGE_FOR_UNCOVERED_INDEX, DEFAULT_SERVER_MERGE_FOR_UNCOVERED_INDEX) .setIfUnset(MAX_IN_LIST_SKIP_SCAN_SIZE, DEFAULT_MAX_IN_LIST_SKIP_SCAN_SIZE) .setIfUnset(CONNECTION_ACTIVITY_LOGGING_ENABLED, DEFAULT_CONNECTION_ACTIVITY_LOGGING_ENABLED) + .setIfUnset(CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED, + DEFAULT_CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED) .setIfUnset(CONNECTION_ACTIVITY_LOGGING_INTERVAL, DEFAULT_CONNECTION_ACTIVITY_LOGGING_INTERVAL_IN_MINS) .setIfUnset(CLUSTER_ROLE_BASED_MUTATION_BLOCK_ENABLED, diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/QueryUtil.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/QueryUtil.java index 6b0ccc643a..e02fe57423 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/QueryUtil.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/QueryUtil.java @@ -137,6 +137,8 @@ public final class QueryUtil { public static final int DATA_TYPE_NAME_POSITION = 6; public static final String IS_SERVER_CONNECTION = "IS_SERVER_CONNECTION"; + public static final String REGIONS = "regions"; + public static final String HOSTNAMES = "hostnames"; private static final String SELECT = "SELECT"; private static final String FROM = "FROM"; private static final String WHERE = "WHERE"; diff --git a/phoenix-core/src/it/java/org/apache/phoenix/end2end/ConnectionIT.java b/phoenix-core/src/it/java/org/apache/phoenix/end2end/ConnectionIT.java index ff872bd639..24d5811e38 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/end2end/ConnectionIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/end2end/ConnectionIT.java @@ -19,6 +19,7 @@ package org.apache.phoenix.end2end; import static org.apache.phoenix.query.BaseTest.setUpConfigForMiniCluster; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNull; import static org.junit.Assume.assumeTrue; import java.sql.Connection; @@ -158,4 +159,37 @@ public class ConnectionIT { } } + + @Test + public void testQueryPlanIsNullByDefault() throws SQLException { + // Test that query plan is null by default even after data operations + String tableName = "TEST_QUERY_PLAN_" + tableCounter++; + + try (PhoenixConnection conn = (PhoenixConnection) DriverManager.getConnection("jdbc:phoenix")) { + // Initially, query plan should be null (disabled by default) + String initialQueryPlan = conn.getActivityLogger().getExplainPlanInfo(); + assertNull("Query plan should be null by default (disabled)", initialQueryPlan); + + // Create table and load data + try (Statement stmt = conn.createStatement()) { + stmt.execute("CREATE TABLE " + tableName + " (id INTEGER PRIMARY KEY, name VARCHAR)"); + stmt.execute("UPSERT INTO " + tableName + " VALUES (1, 'test1')"); + stmt.execute("UPSERT INTO " + tableName + " VALUES (2, 'test2')"); + conn.commit(); + } + + // Execute a query - query plan should still be null since it's disabled by default + try (Statement stmt = conn.createStatement()) { + ResultSet rs = stmt.executeQuery("SELECT * FROM " + tableName); + while (rs.next()) { + // Consume the result set + } + + // Query plan should still be null since it's disabled by default + String queryPlan = conn.getActivityLogger().getExplainPlanInfo(); + assertNull("Query plan should be null after query execution (disabled by default)", + queryPlan); + } + } + } } diff --git a/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingConnectionLimiterIT.java b/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingConnectionLimiterIT.java index 289939c5a4..dd59730ce1 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingConnectionLimiterIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingConnectionLimiterIT.java @@ -23,6 +23,7 @@ import java.sql.Connection; import java.sql.PreparedStatement; import java.sql.ResultSet; import java.sql.SQLException; +import java.sql.Statement; import java.sql.Timestamp; import java.time.Instant; import java.util.ArrayList; @@ -186,6 +187,55 @@ public abstract class LoggingConnectionLimiterIT extends BaseTest { } + @Test + public void testQueryExplainPlan() throws Exception { + + String query = "SELECT * FROM " + tableName; // FULL SCAN + + if (getConnection() instanceof PhoenixConnection) { + try (PhoenixConnection pconn = getConnection().unwrap(PhoenixConnection.class); + Statement stmt = pconn.createStatement()) { + ResultSet rs = stmt.executeQuery(query); + while (rs.next()) { + // do nothing + } + boolean queryPlanFound = false; + String queryPlan = pconn.getActivityLogger().getExplainPlanInfo(); + if ( + queryPlan != null && queryPlan.contains("FULL SCAN") && queryPlan.contains("regions=") + && queryPlan.contains("hostnames=") + ) { + queryPlanFound = true; + + // Extract regions and hostnames efficiently + String regions = extractBetweenBraces(queryPlan, "regions={"); + String hostnames = extractBetweenBraces(queryPlan, "hostnames={"); + + assertFalse("Regions should not be empty", regions.trim().isEmpty()); + assertFalse("Hostnames should not be empty", hostnames.trim().isEmpty()); + + } + assertTrue("Query plan should contain FULL SCAN, regions, and hostnames", queryPlanFound); + } + try (PhoenixConnection pconn = getConnection().unwrap(PhoenixConnection.class);) { + loadData(pconn, "PhoenixTest", "1", 10, 2); + String queryPlan = pconn.getActivityLogger().getExplainPlanInfo(); + assertTrue("Query plan should be empty for non-query operations", queryPlan.isEmpty()); + } + } else { + // for HA case, ignoring as parallelPhoenixConnection object doesn't have activity Logger + // object defined. + assertTrue(getConnection() instanceof ParallelPhoenixConnection); + } + + } + + private String extractBetweenBraces(String text, String marker) { + int start = text.indexOf(marker) + marker.length(); + int end = text.indexOf("}", start); + return text.substring(start, end); + } + protected abstract ConnectionLimiter getConnectionLimiter() throws Exception; protected int runSampleActivity(ActivityType activityType, int clientPool, int clientQueue, diff --git a/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingSingleConnectionLimiterIT.java b/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingSingleConnectionLimiterIT.java index 1c37e4f58b..11798b3986 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingSingleConnectionLimiterIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/jdbc/LoggingSingleConnectionLimiterIT.java @@ -64,6 +64,7 @@ public class LoggingSingleConnectionLimiterIT extends LoggingConnectionLimiterIT conf.set(QueryServices.INTERNAL_CONNECTION_MAX_ALLOWED_CONNECTIONS, String.valueOf(20)); conf.set(PhoenixHAExecutorServiceProvider.HA_MAX_POOL_SIZE, String.valueOf(5)); conf.set(PhoenixHAExecutorServiceProvider.HA_MAX_QUEUE_SIZE, String.valueOf(30)); + conf.set(QueryServices.CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED, String.valueOf(true)); conf.set(HConstants.CLIENT_CONNECTION_REGISTRY_IMPL_CONF_KEY, ZKConnectionInfo.ZK_REGISTRY_NAME); return conf; @@ -77,6 +78,7 @@ public class LoggingSingleConnectionLimiterIT extends LoggingConnectionLimiterIT conf.set(QueryServices.INTERNAL_CONNECTION_MAX_ALLOWED_CONNECTIONS, String.valueOf(20)); conf.set(PhoenixHAExecutorServiceProvider.HA_MAX_POOL_SIZE, String.valueOf(5)); conf.set(PhoenixHAExecutorServiceProvider.HA_MAX_QUEUE_SIZE, String.valueOf(30)); + conf.set(QueryServices.CONNECTION_EXPLAIN_PLAN_LOGGING_ENABLED, String.valueOf(true)); conf.set(HConstants.CLIENT_CONNECTION_REGISTRY_IMPL_CONF_KEY, ZKConnectionInfo.ZK_REGISTRY_NAME); Configuration copy = new Configuration(conf);