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 07f1fea PHOENIX-5981: Wrong multiple counting of resultSetTimeMs and
wallclockTimeMs in OverallQueryMetrics
07f1fea is described below
commit 07f1fea40804a9c65e04e336afbeecab534372e0
Author: Chinmay Kulkarni <chinmayskulka...@gmail.com>
AuthorDate: Tue Jun 30 22:26:48 2020 -0700
PHOENIX-5981: Wrong multiple counting of resultSetTimeMs and
wallclockTimeMs in OverallQueryMetrics
---
.../phoenix/monitoring/MetricsStopWatch.java | 4 +
.../phoenix/monitoring/OverAllQueryMetrics.java | 21 ++-
.../monitoring/OverAllQueryMetricsTest.java | 179 +++++++++++++++++++++
3 files changed, 202 insertions(+), 2 deletions(-)
diff --git
a/phoenix-core/src/main/java/org/apache/phoenix/monitoring/MetricsStopWatch.java
b/phoenix-core/src/main/java/org/apache/phoenix/monitoring/MetricsStopWatch.java
index a852ca9..5b74896 100644
---
a/phoenix-core/src/main/java/org/apache/phoenix/monitoring/MetricsStopWatch.java
+++
b/phoenix-core/src/main/java/org/apache/phoenix/monitoring/MetricsStopWatch.java
@@ -49,6 +49,10 @@ final class MetricsStopWatch {
}
}
}
+
+ boolean isRunning() {
+ return isMetricsEnabled && stopwatch.isRunning();
+ }
long getElapsedTimeInMs() {
if (isMetricsEnabled) {
diff --git
a/phoenix-core/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
b/phoenix-core/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
index 6202eee..ae3edab 100644
---
a/phoenix-core/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
+++
b/phoenix-core/src/main/java/org/apache/phoenix/monitoring/OverAllQueryMetrics.java
@@ -27,6 +27,7 @@ import static
org.apache.phoenix.monitoring.MetricType.WALL_CLOCK_TIME_MS;
import java.util.HashMap;
import java.util.Map;
+import com.google.common.annotations.VisibleForTesting;
import org.apache.phoenix.log.LogLevel;
/**
@@ -82,8 +83,11 @@ public class OverAllQueryMetrics {
}
public void endQuery() {
+ boolean wasRunning = queryWatch.isRunning();
queryWatch.stop();
- wallClockTimeMS.change(queryWatch.getElapsedTimeInMs());
+ if (wasRunning) {
+ wallClockTimeMS.change(queryWatch.getElapsedTimeInMs());
+ }
}
public void startResultSetWatch() {
@@ -91,8 +95,21 @@ public class OverAllQueryMetrics {
}
public void stopResultSetWatch() {
+ boolean wasRunning = resultSetWatch.isRunning();
resultSetWatch.stop();
- resultSetTimeMS.change(resultSetWatch.getElapsedTimeInMs());
+ if (wasRunning) {
+ resultSetTimeMS.change(resultSetWatch.getElapsedTimeInMs());
+ }
+ }
+
+ @VisibleForTesting
+ long getWallClockTimeMs() {
+ return wallClockTimeMS.getValue();
+ }
+
+ @VisibleForTesting
+ long getResultSetTimeMs() {
+ return resultSetTimeMS.getValue();
}
public Map<MetricType, Long> publish() {
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
new file mode 100644
index 0000000..f97731d
--- /dev/null
+++
b/phoenix-core/src/test/java/org/apache/phoenix/monitoring/OverAllQueryMetricsTest.java
@@ -0,0 +1,179 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements. See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership. The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.phoenix.monitoring;
+
+import org.apache.phoenix.log.LogLevel;
+import org.apache.phoenix.util.EnvironmentEdge;
+import org.apache.phoenix.util.EnvironmentEdgeManager;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
+
+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.junit.Assert.assertEquals;
+
+public class OverAllQueryMetricsTest {
+
+ private OverAllQueryMetrics overAllQueryMetrics;
+ private static final long numParallelScans = 10L;
+ private static final long delta = 1000L;
+ private static final int queryTimeouts = 5;
+ private static final int queryFailures = 8;
+ private static final int cacheRefreshesDueToSplits = 15;
+
+ @Before
+ public void getFreshMetricsObject() {
+ overAllQueryMetrics = new OverAllQueryMetrics(true, LogLevel.TRACE);
+ populateMetrics(overAllQueryMetrics, numParallelScans, queryTimeouts,
queryFailures,
+ cacheRefreshesDueToSplits);
+ }
+
+ @After
+ public void reset() {
+ EnvironmentEdgeManager.reset();
+ }
+
+ private static class MyClock extends EnvironmentEdge {
+ private long time;
+ private long delta;
+
+ public MyClock(long time, long delta) {
+ this.time = time;
+ this.delta = delta;
+ }
+
+ @Override public long currentTime() {
+ long prevTime = this.time;
+ this.time += this.delta;
+ return prevTime;
+ }
+ }
+
+ @Test
+ public void testQueryWatchTimer() {
+ assertEquals(0L, overAllQueryMetrics.getWallClockTimeMs());
+ MyClock clock = new MyClock(10L, delta);
+ EnvironmentEdgeManager.injectEdge(clock);
+ overAllQueryMetrics.startQuery();
+ overAllQueryMetrics.endQuery();
+ assertEquals(delta, overAllQueryMetrics.getWallClockTimeMs());
+ // Ensure that calling endQuery() again doesn't change the
wallClockTimeMs
+ overAllQueryMetrics.endQuery();
+ assertEquals(delta, overAllQueryMetrics.getWallClockTimeMs());
+ }
+
+ @Test
+ public void testResultSetWatch() {
+ assertEquals(0L, overAllQueryMetrics.getResultSetTimeMs());
+ MyClock clock = new MyClock(10L, delta);
+ EnvironmentEdgeManager.injectEdge(clock);
+ overAllQueryMetrics.startResultSetWatch();
+ overAllQueryMetrics.stopResultSetWatch();
+ assertEquals(delta, overAllQueryMetrics.getResultSetTimeMs());
+ // Ensure that calling stopResultSetWatch() again doesn't change the
resultSetTimeMs
+ overAllQueryMetrics.stopResultSetWatch();
+ assertEquals(delta, overAllQueryMetrics.getResultSetTimeMs());
+ }
+
+ @Test
+ public void testPublish() {
+ MyClock clock = new MyClock(10L, delta);
+ EnvironmentEdgeManager.injectEdge(clock);
+ overAllQueryMetrics.startQuery();
+ overAllQueryMetrics.startResultSetWatch();
+ assertPublishedMetrics(overAllQueryMetrics.publish(),
numParallelScans, queryTimeouts,
+ queryFailures, cacheRefreshesDueToSplits, 0L);
+ overAllQueryMetrics.endQuery();
+ overAllQueryMetrics.stopResultSetWatch();
+ // expect 2 * delta since we call both endQuery() and
stopResultSetWatch()
+ assertPublishedMetrics(overAllQueryMetrics.publish(),
numParallelScans, queryTimeouts,
+ queryFailures, cacheRefreshesDueToSplits, 2*delta);
+ }
+
+ @Test
+ public void testReset() {
+ assertPublishedMetrics(overAllQueryMetrics.publish(),
numParallelScans, queryTimeouts,
+ queryFailures, cacheRefreshesDueToSplits, 0L);
+ overAllQueryMetrics.reset();
+ assertPublishedMetrics(overAllQueryMetrics.publish(), 0L, 0L, 0L, 0L,
0L);
+ }
+
+ @Test
+ public void testCombine() {
+ OverAllQueryMetrics otherMetrics = new OverAllQueryMetrics(true,
LogLevel.TRACE);
+ final long otherNumParallelScans = 9L;
+ final int otherQueryTimeouts = 8;
+ final int otherQueryFailures = 7;
+ final int otherCacheRefreshes = 6;
+ populateMetrics(otherMetrics, otherNumParallelScans,
otherQueryTimeouts, otherQueryFailures,
+ otherCacheRefreshes);
+ OverAllQueryMetrics finalMetricObj =
this.overAllQueryMetrics.combine(otherMetrics);
+ assertPublishedMetrics(finalMetricObj.publish(), numParallelScans +
otherNumParallelScans,
+ queryTimeouts + otherQueryTimeouts, queryFailures +
otherQueryFailures,
+ cacheRefreshesDueToSplits + otherCacheRefreshes, 0L);
+ }
+
+ @Test
+ public void testNoOpRequestMetricsIfRequestMetricsDisabled() {
+ OverAllQueryMetrics noOpMetrics = new OverAllQueryMetrics(false,
LogLevel.OFF);
+ populateMetrics(noOpMetrics, numParallelScans, queryTimeouts,
queryFailures,
+ cacheRefreshesDueToSplits);
+ Map<MetricType, Long> noOpMap = noOpMetrics.publish();
+ assertEquals(1, noOpMap.size());
+ assertEquals(0L, (long)noOpMap.get(NO_OP_METRIC));
+ }
+
+ private void populateMetrics(OverAllQueryMetrics metricsObj, long
numParallelScansSetting,
+ int queryTimeoutsSetting, int queryFailuresSetting,
+ int cacheRefreshesDueToSplitsSetting) {
+ metricsObj.updateNumParallelScans(numParallelScansSetting);
+ for (int i = 0; i < queryTimeoutsSetting; i++) {
+ metricsObj.queryTimedOut();
+ }
+ for (int i = 0; i < queryFailuresSetting; i++) {
+ metricsObj.queryFailed();
+ }
+ for (int i = 0; i < cacheRefreshesDueToSplitsSetting; i++) {
+ metricsObj.cacheRefreshedDueToSplits();
+ }
+ }
+
+ private void assertPublishedMetrics(
+ final Map<MetricType, Long> metrics,
+ final long expectedNumParallelScans,
+ final long expectedQueryTimeouts,
+ final long expectedQueryFailures,
+ final long expectedCacheRefreshes,
+ final long expectedElapsedTime) {
+ 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));
+ }
+
+}
