You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@phoenix.apache.org by ch...@apache.org on 2020/07/15 22:52:12 UTC

[phoenix] branch master updated: PHOENIX-5984: Query timeout counter is not updated in all timeouts cases

This is an automated email from the ASF dual-hosted git repository.

chinmayskulkarni 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 2fe1dd0  PHOENIX-5984: Query timeout counter is not updated in all timeouts cases
2fe1dd0 is described below

commit 2fe1dd0f4ea962554443d11d65aa44d9361d888b
Author: Chinmay Kulkarni <ch...@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   |  2 +-
 .../phoenix/monitoring/PhoenixMetricsIT.java       | 88 +++++++++++++++++-----
 .../phoenix/iterate/BaseResultIterators.java       | 15 +++-
 3 files changed, 82 insertions(+), 23 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 8234c1c..85bbae7 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
@@ -28,7 +28,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 53fcf92..5d027e1 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;
@@ -70,6 +72,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;
@@ -92,6 +96,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();
@@ -244,28 +265,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
@@ -293,6 +318,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 fdc021d..09d5861 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;
@@ -1316,7 +1317,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
@@ -1381,10 +1384,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);