This is an automated email from the ASF dual-hosted git repository. chinmayskulkarni pushed a commit to branch 4.x in repository https://gitbox.apache.org/repos/asf/phoenix.git
The following commit(s) were added to refs/heads/4.x by this push: new db9dcca PHOENIX-5984: Query timeout counter is not updated in all timeouts cases db9dcca is described below commit db9dccae63f6008fdb3518de70b4dc00464d20e8 Author: Chinmay Kulkarni <chinmayskulka...@gmail.com> AuthorDate: Wed Jul 1 19:57:17 2020 -0700 PHOENIX-5984: Query timeout counter is not updated in all timeouts cases --- .../monitoring/GlobalPhoenixMetricsTestSink.java | 9 +-- .../phoenix/monitoring/PhoenixMetricsIT.java | 88 +++++++++++++++++----- .../phoenix/iterate/BaseResultIterators.java | 15 +++- 3 files changed, 82 insertions(+), 30 deletions(-) diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/GlobalPhoenixMetricsTestSink.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/GlobalPhoenixMetricsTestSink.java index 10ff2e1..813df6b 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/GlobalPhoenixMetricsTestSink.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/GlobalPhoenixMetricsTestSink.java @@ -22,13 +22,6 @@ import org.apache.commons.configuration.SubsetConfiguration; import org.apache.hadoop.metrics2.AbstractMetric; import org.apache.hadoop.metrics2.MetricsRecord; import org.apache.hadoop.metrics2.MetricsSink; -import org.apache.phoenix.util.PhoenixRuntime; - -import java.util.Map; - -import static junit.framework.TestCase.assertTrue; -import static org.junit.Assert.assertEquals; -import static org.junit.Assert.fail; public class GlobalPhoenixMetricsTestSink implements MetricsSink { @@ -36,7 +29,7 @@ public class GlobalPhoenixMetricsTestSink implements MetricsSink { // PhoenixMetricsIT tests verifies these metrics from this sink in a separate thread // GlobalPhoenixMetricsTestSink is invoked based on time defined in hadoop-metrics2.properties // This lock is to prevent concurrent access to metrics Iterable for these threads - static Object lock = new Object(); + static final Object lock = new Object(); static Iterable<AbstractMetric> metrics; @Override 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 946a929..e8d9e40 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 @@ -9,6 +9,7 @@ */ package org.apache.phoenix.monitoring; +import static org.apache.phoenix.exception.SQLExceptionCode.OPERATION_TIMED_OUT; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_FAILED_QUERY_COUNTER; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_HBASE_COUNT_BYTES_REGION_SERVER_RESULTS; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_HBASE_COUNT_MILLS_BETWEEN_NEXTS; @@ -35,6 +36,7 @@ import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_SPOOL_FIL 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.MEMORY_CHUNK_BYTES; +import static org.apache.phoenix.monitoring.MetricType.QUERY_TIMEOUT_COUNTER; 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.util.PhoenixRuntime.TENANT_ID_ATTRIB; @@ -71,6 +73,8 @@ import org.apache.phoenix.jdbc.PhoenixDriver; import org.apache.phoenix.jdbc.PhoenixResultSet; import org.apache.phoenix.log.LogLevel; import org.apache.phoenix.query.QueryServices; +import org.apache.phoenix.util.EnvironmentEdge; +import org.apache.phoenix.util.EnvironmentEdgeManager; import org.apache.phoenix.util.PhoenixRuntime; import org.hamcrest.CoreMatchers; import org.junit.Test; @@ -93,6 +97,23 @@ public class PhoenixMetricsIT extends BasePhoenixMetricsIT { private static final Logger LOGGER = LoggerFactory.getLogger(PhoenixMetricsIT.class); + private static class MyClock extends EnvironmentEdge { + private long time; + private final long delay; + + public MyClock (long time, long delay) { + this.time = time; + this.delay = delay; + } + + @Override + public long currentTime() { + long currentTime = this.time; + this.time += this.delay; + return currentTime; + } + } + @Test public void testResetGlobalPhoenixMetrics() throws Exception { resetGlobalMetrics(); @@ -249,28 +270,32 @@ public class PhoenixMetricsIT extends BasePhoenixMetricsIT { } } } - assertTrue("Metric expected but not present in Hadoop Metrics Sink (GlobalPhoenixMetricsTestSink)", - expectedMetrics.size() == 0); + assertEquals("Metric expected but not present in Hadoop Metrics Sink " + + "(GlobalPhoenixMetricsTestSink)", 0, expectedMetrics.size()); return true; } - private static void createTableAndInsertValues(String tableName, boolean resetGlobalMetricsAfterTableCreate) - throws Exception { - String ddl = "CREATE TABLE " + tableName + " (K VARCHAR NOT NULL PRIMARY KEY, V VARCHAR)"; - Connection conn = DriverManager.getConnection(getUrl()); - conn.createStatement().execute(ddl); - if (resetGlobalMetricsAfterTableCreate) { - resetGlobalMetrics(); - } - // executing 10 upserts/mutations. - String dml = "UPSERT INTO " + tableName + " VALUES (?, ?)"; - PreparedStatement stmt = conn.prepareStatement(dml); - for (int i = 1; i <= 10; i++) { - stmt.setString(1, "key" + i); - stmt.setString(2, "value" + i); - stmt.executeUpdate(); + private static void createTableAndInsertValues(String tableName, + boolean resetGlobalMetricsAfterTableCreate) throws SQLException { + String ddl = String.format("CREATE TABLE %s (K VARCHAR NOT NULL PRIMARY KEY, V VARCHAR)", + tableName); + try (Connection conn = DriverManager.getConnection(getUrl()); + Statement stmt = conn.createStatement()) { + stmt.execute(ddl); + if (resetGlobalMetricsAfterTableCreate) { + resetGlobalMetrics(); + } + // executing 10 upserts/mutations. + String dml = String.format("UPSERT INTO %s VALUES (?, ?)", tableName); + try(PreparedStatement prepStmt = conn.prepareStatement(dml)) { + for (int i = 1; i <= 10; i++) { + prepStmt.setString(1, "key" + i); + prepStmt.setString(2, "value" + i); + prepStmt.executeUpdate(); + } + } + conn.commit(); } - conn.commit(); } @Test @@ -298,6 +323,33 @@ public class PhoenixMetricsIT extends BasePhoenixMetricsIT { } @Test + public void testMetricsForSelectFetchResultsTimeout() throws SQLException { + String tableName = generateUniqueName(); + final int queryTimeout = 10; //seconds + createTableAndInsertValues(tableName, true); + try (Connection conn = DriverManager.getConnection(getUrl()); + Statement stmt = conn.createStatement()) { + stmt.setQueryTimeout(queryTimeout); + ResultSet rs = stmt.executeQuery(String.format("SELECT * FROM %s", tableName)); + // Make the query time out with a longer delay than the set query timeout value (in ms) + MyClock clock = new MyClock(10, queryTimeout * 2 * 1000); + EnvironmentEdgeManager.injectEdge(clock); + try { + rs.next(); + fail(); + } catch (SQLException e) { + assertEquals(OPERATION_TIMED_OUT.getErrorCode(), e.getErrorCode()); + } + Map<MetricType, Long> overallReadMetrics = + PhoenixRuntime.getOverAllReadRequestMetricInfo(rs); + assertEquals(1L, (long)overallReadMetrics.get(QUERY_TIMEOUT_COUNTER)); + assertEquals(1L, GLOBAL_QUERY_TIMEOUT_COUNTER.getMetric().getValue()); + } finally { + EnvironmentEdgeManager.reset(); + } + } + + @Test public void testReadMetricsForSelect() throws Exception { String tableName = generateUniqueName(); long numSaltBuckets = 6; diff --git a/phoenix-core/src/main/java/org/apache/phoenix/iterate/BaseResultIterators.java b/phoenix-core/src/main/java/org/apache/phoenix/iterate/BaseResultIterators.java index c54a472..c271487 100644 --- a/phoenix-core/src/main/java/org/apache/phoenix/iterate/BaseResultIterators.java +++ b/phoenix-core/src/main/java/org/apache/phoenix/iterate/BaseResultIterators.java @@ -21,6 +21,7 @@ import static org.apache.phoenix.coprocessor.BaseScannerRegionObserver.LOCAL_IND import static org.apache.phoenix.coprocessor.BaseScannerRegionObserver.SCAN_ACTUAL_START_ROW; import static org.apache.phoenix.coprocessor.BaseScannerRegionObserver.SCAN_START_ROW_SUFFIX; import static org.apache.phoenix.coprocessor.BaseScannerRegionObserver.SCAN_STOP_ROW_SUFFIX; +import static org.apache.phoenix.exception.SQLExceptionCode.OPERATION_TIMED_OUT; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_FAILED_QUERY_COUNTER; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_QUERY_TIMEOUT_COUNTER; import static org.apache.phoenix.query.QueryServices.WILDCARD_QUERY_DYNAMIC_COLS_ATTRIB; @@ -1317,7 +1318,9 @@ public abstract class BaseResultIterators extends ExplainTable implements Result try { long timeOutForScan = maxQueryEndTime - EnvironmentEdgeManager.currentTimeMillis(); if (timeOutForScan < 0) { - throw new SQLExceptionInfo.Builder(SQLExceptionCode.OPERATION_TIMED_OUT).setMessage(". Query couldn't be completed in the alloted time: " + queryTimeOut + " ms").build().buildException(); + throw new SQLExceptionInfo.Builder(OPERATION_TIMED_OUT).setMessage( + ". Query couldn't be completed in the allotted time: " + + queryTimeOut + " ms").build().buildException(); } // make sure we apply the iterators in order if (isLocalIndex && previousScan != null && previousScan.getScan() != null @@ -1382,10 +1385,14 @@ public abstract class BaseResultIterators extends ExplainTable implements Result context.getOverallQueryMetrics().queryTimedOut(); GLOBAL_QUERY_TIMEOUT_COUNTER.increment(); // thrown when a thread times out waiting for the future.get() call to return - toThrow = new SQLExceptionInfo.Builder(SQLExceptionCode.OPERATION_TIMED_OUT) - .setMessage(". Query couldn't be completed in the alloted time: " + queryTimeOut + " ms") - .setRootCause(e).build().buildException(); + toThrow = new SQLExceptionInfo.Builder(OPERATION_TIMED_OUT) + .setMessage(". Query couldn't be completed in the allotted time: " + + queryTimeOut + " ms").setRootCause(e).build().buildException(); } catch (SQLException e) { + if (e.getErrorCode() == OPERATION_TIMED_OUT.getErrorCode()) { + context.getOverallQueryMetrics().queryTimedOut(); + GLOBAL_QUERY_TIMEOUT_COUNTER.increment(); + } toThrow = e; } catch (Exception e) { toThrow = ServerUtil.parseServerException(e);