You are viewing a plain text version of this content. The canonical link for it is here.
Posted to common-commits@hadoop.apache.org by xi...@apache.org on 2017/11/10 05:06:09 UTC
hadoop git commit: HADOOP-14960. Add GC time percentage
monitor/alerter. Contributed by Misha Dmitriev.
Repository: hadoop
Updated Branches:
refs/heads/trunk 10a1f557e -> 3c6adda29
HADOOP-14960. Add GC time percentage monitor/alerter. Contributed by Misha Dmitriev.
Project: http://git-wip-us.apache.org/repos/asf/hadoop/repo
Commit: http://git-wip-us.apache.org/repos/asf/hadoop/commit/3c6adda2
Tree: http://git-wip-us.apache.org/repos/asf/hadoop/tree/3c6adda2
Diff: http://git-wip-us.apache.org/repos/asf/hadoop/diff/3c6adda2
Branch: refs/heads/trunk
Commit: 3c6adda291745c592741b87cd613214ae11887e4
Parents: 10a1f55
Author: Xiao Chen <xi...@apache.org>
Authored: Thu Nov 9 21:05:34 2017 -0800
Committer: Xiao Chen <xi...@apache.org>
Committed: Thu Nov 9 21:06:06 2017 -0800
----------------------------------------------------------------------
.../hadoop/metrics2/source/JvmMetrics.java | 15 ++
.../hadoop/metrics2/source/JvmMetricsInfo.java | 3 +-
.../org/apache/hadoop/util/GcTimeMonitor.java | 242 +++++++++++++++++++
.../hadoop/metrics2/source/TestJvmMetrics.java | 92 ++++++-
4 files changed, 345 insertions(+), 7 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/hadoop/blob/3c6adda2/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetrics.java
----------------------------------------------------------------------
diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetrics.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetrics.java
index e3f8754..8c3375f 100644
--- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetrics.java
+++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetrics.java
@@ -28,6 +28,8 @@ import java.util.List;
import java.util.concurrent.ConcurrentHashMap;
import com.google.common.annotations.VisibleForTesting;
+import com.google.common.base.Preconditions;
+
import org.apache.hadoop.classification.InterfaceAudience;
import org.apache.hadoop.log.metrics.EventCounter;
import org.apache.hadoop.metrics2.MetricsCollector;
@@ -39,6 +41,8 @@ import org.apache.hadoop.metrics2.lib.DefaultMetricsSystem;
import org.apache.hadoop.metrics2.lib.Interns;
import static org.apache.hadoop.metrics2.source.JvmMetricsInfo.*;
import static org.apache.hadoop.metrics2.impl.MsInfo.*;
+
+import org.apache.hadoop.util.GcTimeMonitor;
import org.apache.hadoop.util.JvmPauseMonitor;
/**
@@ -85,6 +89,7 @@ public class JvmMetrics implements MetricsSource {
private JvmPauseMonitor pauseMonitor = null;
final ConcurrentHashMap<String, MetricsInfo[]> gcInfoCache =
new ConcurrentHashMap<String, MetricsInfo[]>();
+ private GcTimeMonitor gcTimeMonitor = null;
@VisibleForTesting
JvmMetrics(String processName, String sessionId) {
@@ -96,6 +101,11 @@ public class JvmMetrics implements MetricsSource {
this.pauseMonitor = pauseMonitor;
}
+ public void setGcTimeMonitor(GcTimeMonitor gcTimeMonitor) {
+ Preconditions.checkNotNull(gcTimeMonitor);
+ this.gcTimeMonitor = gcTimeMonitor;
+ }
+
public static JvmMetrics create(String processName, String sessionId,
MetricsSystem ms) {
return ms.register(JvmMetrics.name(), JvmMetrics.description(),
@@ -176,6 +186,11 @@ public class JvmMetrics implements MetricsSource {
rb.addCounter(GcTotalExtraSleepTime,
pauseMonitor.getTotalGcExtraSleepTime());
}
+
+ if (gcTimeMonitor != null) {
+ rb.addCounter(GcTimePercentage,
+ gcTimeMonitor.getLatestGcData().getGcTimePercentage());
+ }
}
private MetricsInfo[] getGcInfo(String gcName) {
http://git-wip-us.apache.org/repos/asf/hadoop/blob/3c6adda2/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetricsInfo.java
----------------------------------------------------------------------
diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetricsInfo.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetricsInfo.java
index 8da6785..74f670b 100644
--- a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetricsInfo.java
+++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/metrics2/source/JvmMetricsInfo.java
@@ -51,7 +51,8 @@ public enum JvmMetricsInfo implements MetricsInfo {
LogInfo("Total number of info log events"),
GcNumWarnThresholdExceeded("Number of times that the GC warn threshold is exceeded"),
GcNumInfoThresholdExceeded("Number of times that the GC info threshold is exceeded"),
- GcTotalExtraSleepTime("Total GC extra sleep time in milliseconds");
+ GcTotalExtraSleepTime("Total GC extra sleep time in milliseconds"),
+ GcTimePercentage("Percentage of time the JVM was paused in GC");
private final String desc;
http://git-wip-us.apache.org/repos/asf/hadoop/blob/3c6adda2/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/GcTimeMonitor.java
----------------------------------------------------------------------
diff --git a/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/GcTimeMonitor.java b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/GcTimeMonitor.java
new file mode 100644
index 0000000..0640fc0
--- /dev/null
+++ b/hadoop-common-project/hadoop-common/src/main/java/org/apache/hadoop/util/GcTimeMonitor.java
@@ -0,0 +1,242 @@
+/**
+ * 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.hadoop.util;
+
+import com.google.common.base.Preconditions;
+
+import java.lang.management.GarbageCollectorMXBean;
+import java.lang.management.ManagementFactory;
+import java.util.List;
+
+/**
+ * This class monitors the percentage of time the JVM is paused in GC within
+ * the specified observation window, say 1 minute. The user can provide a
+ * hook which will be called whenever this percentage exceeds the specified
+ * threshold.
+ */
+public class GcTimeMonitor extends Thread {
+
+ private final long maxGcTimePercentage;
+ private final long observationWindowMs, sleepIntervalMs;
+ private final GcTimeAlertHandler alertHandler;
+
+ private final List<GarbageCollectorMXBean> gcBeans =
+ ManagementFactory.getGarbageCollectorMXBeans();
+ // Ring buffers containing GC timings and timestamps when timings were taken
+ private final TsAndData[] gcDataBuf;
+ private int bufSize, startIdx, endIdx;
+
+ private long startTime;
+ private final GcData curData = new GcData();
+ private volatile boolean shouldRun = true;
+
+ /**
+ * Create an instance of GCTimeMonitor. Once it's started, it will stay alive
+ * and monitor GC time percentage until shutdown() is called. If you don't
+ * put a limit on the number of GCTimeMonitor instances that you create, and
+ * alertHandler != null, you should necessarily call shutdown() once the given
+ * instance is not needed. Otherwise, you may create a memory leak, because
+ * each running GCTimeMonitor will keep its alertHandler object in memory,
+ * which in turn may reference and keep in memory many more other objects.
+ *
+ * @param observationWindowMs the interval over which the percentage
+ * of GC time should be calculated. A practical value would be somewhere
+ * between 30 sec and several minutes.
+ * @param sleepIntervalMs how frequently this thread should wake up to check
+ * GC timings. This is also a frequency with which alertHandler will be
+ * invoked if GC time percentage exceeds the specified limit. A practical
+ * value would likely be 500..1000 ms.
+ * @param maxGcTimePercentage A GC time percentage limit (0..100) within
+ * observationWindowMs. Once this is exceeded, alertHandler will be
+ * invoked every sleepIntervalMs milliseconds until GC time percentage
+ * falls below this limit.
+ * @param alertHandler a single method in this interface is invoked when GC
+ * time percentage exceeds the specified limit.
+ */
+ public GcTimeMonitor(long observationWindowMs, long sleepIntervalMs,
+ int maxGcTimePercentage, GcTimeAlertHandler alertHandler) {
+ Preconditions.checkArgument(observationWindowMs > 0);
+ Preconditions.checkArgument(
+ sleepIntervalMs > 0 && sleepIntervalMs < observationWindowMs);
+ Preconditions.checkArgument(
+ maxGcTimePercentage >= 0 && maxGcTimePercentage <= 100);
+
+ this.observationWindowMs = observationWindowMs;
+ this.sleepIntervalMs = sleepIntervalMs;
+ this.maxGcTimePercentage = maxGcTimePercentage;
+ this.alertHandler = alertHandler;
+
+ bufSize = (int) (observationWindowMs / sleepIntervalMs + 2);
+ // Prevent the user from accidentally creating an abnormally big buffer,
+ // which will result in slow calculations and likely inaccuracy.
+ Preconditions.checkArgument(bufSize <= 128 * 1024);
+ gcDataBuf = new TsAndData[bufSize];
+ for (int i = 0; i < bufSize; i++) {
+ gcDataBuf[i] = new TsAndData();
+ }
+
+ this.setDaemon(true);
+ this.setName("GcTimeMonitor obsWindow = " + observationWindowMs +
+ ", sleepInterval = " + sleepIntervalMs +
+ ", maxGcTimePerc = " + maxGcTimePercentage);
+ }
+
+ @Override
+ public void run() {
+ startTime = System.currentTimeMillis();
+ curData.timestamp = startTime;
+ gcDataBuf[startIdx].setValues(startTime, 0);
+
+ while (shouldRun) {
+ try {
+ Thread.sleep(sleepIntervalMs);
+ } catch (InterruptedException ie) {
+ return;
+ }
+
+ calculateGCTimePercentageWithinObservedInterval();
+ if (alertHandler != null &&
+ curData.gcTimePercentage > maxGcTimePercentage) {
+ alertHandler.alert(curData.clone());
+ }
+ }
+ }
+
+ public void shutdown() {
+ shouldRun = false;
+ }
+
+ /** Returns a copy of the most recent data measured by this monitor. */
+ public GcData getLatestGcData() {
+ return curData.clone();
+ }
+
+ private void calculateGCTimePercentageWithinObservedInterval() {
+ long prevTotalGcTime = curData.totalGcTime;
+ long totalGcTime = 0;
+ long totalGcCount = 0;
+ for (GarbageCollectorMXBean gcBean : gcBeans) {
+ totalGcTime += gcBean.getCollectionTime();
+ totalGcCount += gcBean.getCollectionCount();
+ }
+ long gcTimeWithinSleepInterval = totalGcTime - prevTotalGcTime;
+
+ long ts = System.currentTimeMillis();
+ long gcMonitorRunTime = ts - startTime;
+
+ endIdx = (endIdx + 1) % bufSize;
+ gcDataBuf[endIdx].setValues(ts, gcTimeWithinSleepInterval);
+
+ // Move startIdx forward until we reach the first buffer entry with
+ // timestamp within the observation window.
+ long startObsWindowTs = ts - observationWindowMs;
+ while (gcDataBuf[startIdx].ts < startObsWindowTs && startIdx != endIdx) {
+ startIdx = (startIdx + 1) % bufSize;
+ }
+
+ // Calculate total GC time within observationWindowMs.
+ // We should be careful about GC time that passed before the first timestamp
+ // in our observation window.
+ long gcTimeWithinObservationWindow = Math.min(
+ gcDataBuf[startIdx].gcPause, gcDataBuf[startIdx].ts - startObsWindowTs);
+ if (startIdx != endIdx) {
+ for (int i = (startIdx + 1) % bufSize; i != endIdx;
+ i = (i + 1) % bufSize) {
+ gcTimeWithinObservationWindow += gcDataBuf[i].gcPause;
+ }
+ }
+
+ curData.update(ts, gcMonitorRunTime, totalGcTime, totalGcCount,
+ (int) (gcTimeWithinObservationWindow * 100 /
+ Math.min(observationWindowMs, gcMonitorRunTime)));
+ }
+
+ /**
+ * The user can provide an instance of a class implementing this interface
+ * when initializing a GcTimeMonitor to receive alerts when GC time
+ * percentage exceeds the specified threshold.
+ */
+ public interface GcTimeAlertHandler {
+ void alert(GcData gcData);
+ }
+
+ /** Encapsulates data about GC pauses measured at the specific timestamp. */
+ public static class GcData implements Cloneable {
+ private long timestamp;
+ private long gcMonitorRunTime, totalGcTime, totalGcCount;
+ private int gcTimePercentage;
+
+ /** Returns the absolute timestamp when this measurement was taken. */
+ public long getTimestamp() {
+ return timestamp;
+ }
+
+ /** Returns the time since the start of the associated GcTimeMonitor. */
+ public long getGcMonitorRunTime() {
+ return gcMonitorRunTime;
+ }
+
+ /** Returns accumulated GC time since this JVM started. */
+ public long getAccumulatedGcTime() {
+ return totalGcTime;
+ }
+
+ /** Returns the accumulated number of GC pauses since this JVM started. */
+ public long getAccumulatedGcCount() {
+ return totalGcCount;
+ }
+
+ /**
+ * Returns the percentage (0..100) of time that the JVM spent in GC pauses
+ * within the observation window of the associated GcTimeMonitor.
+ */
+ public int getGcTimePercentage() {
+ return gcTimePercentage;
+ }
+
+ private synchronized void update(long inTimestamp, long inGcMonitorRunTime,
+ long inTotalGcTime, long inTotalGcCount, int inGcTimePercentage) {
+ this.timestamp = inTimestamp;
+ this.gcMonitorRunTime = inGcMonitorRunTime;
+ this.totalGcTime = inTotalGcTime;
+ this.totalGcCount = inTotalGcCount;
+ this.gcTimePercentage = inGcTimePercentage;
+ }
+
+ @Override
+ public synchronized GcData clone() {
+ try {
+ return (GcData) super.clone();
+ } catch (CloneNotSupportedException e) {
+ throw new RuntimeException(e);
+ }
+ }
+ }
+
+ private static class TsAndData {
+ private long ts; // Timestamp when this measurement was taken
+ private long gcPause; // Total GC pause time within the interval between ts
+ // and the timestamp of the previous measurement.
+
+ void setValues(long inTs, long inGcPause) {
+ this.ts = inTs;
+ this.gcPause = inGcPause;
+ }
+ }
+}
http://git-wip-us.apache.org/repos/asf/hadoop/blob/3c6adda2/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/metrics2/source/TestJvmMetrics.java
----------------------------------------------------------------------
diff --git a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/metrics2/source/TestJvmMetrics.java b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/metrics2/source/TestJvmMetrics.java
index 69e7565..5320b6e 100644
--- a/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/metrics2/source/TestJvmMetrics.java
+++ b/hadoop-common-project/hadoop-common/src/test/java/org/apache/hadoop/metrics2/source/TestJvmMetrics.java
@@ -18,6 +18,7 @@
package org.apache.hadoop.metrics2.source;
+import org.apache.hadoop.util.GcTimeMonitor;
import org.junit.After;
import org.junit.Assert;
import org.junit.Rule;
@@ -35,6 +36,9 @@ import org.apache.hadoop.service.ServiceStateException;
import org.apache.hadoop.test.GenericTestUtils;
import org.apache.hadoop.util.JvmPauseMonitor;
+import java.util.ArrayList;
+import java.util.List;
+
import static org.apache.hadoop.metrics2.source.JvmMetricsInfo.*;
import static org.apache.hadoop.metrics2.impl.MsInfo.*;
@@ -43,17 +47,21 @@ public class TestJvmMetrics {
@Rule
public Timeout timeout = new Timeout(30000);
private JvmPauseMonitor pauseMonitor;
+ private GcTimeMonitor gcTimeMonitor;
/**
- * Robust shutdown of the pause monitor if it hasn't been stopped already.
+ * Robust shutdown of the monitors if they haven't been stopped already.
*/
@After
public void teardown() {
ServiceOperations.stop(pauseMonitor);
+ if (gcTimeMonitor != null) {
+ gcTimeMonitor.shutdown();
+ }
}
@Test
- public void testPresence() {
+ public void testJvmPauseMonitorPresence() {
pauseMonitor = new JvmPauseMonitor();
pauseMonitor.init(new Configuration());
pauseMonitor.start();
@@ -66,14 +74,35 @@ public class TestJvmMetrics {
verify(rb).tag(ProcessName, "test");
verify(rb).tag(SessionId, "test");
for (JvmMetricsInfo info : JvmMetricsInfo.values()) {
- if (info.name().startsWith("Mem"))
+ if (info.name().startsWith("Mem")) {
verify(rb).addGauge(eq(info), anyFloat());
- else if (info.name().startsWith("Gc"))
+ } else if (info.name().startsWith("Gc") &&
+ !info.name().equals("GcTimePercentage")) {
verify(rb).addCounter(eq(info), anyLong());
- else if (info.name().startsWith("Threads"))
+ } else if (info.name().startsWith("Threads")) {
verify(rb).addGauge(eq(info), anyInt());
- else if (info.name().startsWith("Log"))
+ } else if (info.name().startsWith("Log")) {
verify(rb).addCounter(eq(info), anyLong());
+ }
+ }
+ }
+
+ @Test
+ public void testGcTimeMonitorPresence() {
+ gcTimeMonitor = new GcTimeMonitor(60000, 1000, 70, null);
+ gcTimeMonitor.start();
+ JvmMetrics jvmMetrics = new JvmMetrics("test", "test");
+ jvmMetrics.setGcTimeMonitor(gcTimeMonitor);
+ MetricsRecordBuilder rb = getMetrics(jvmMetrics);
+ MetricsCollector mc = rb.parent();
+
+ verify(mc).addRecord(JvmMetrics);
+ verify(rb).tag(ProcessName, "test");
+ verify(rb).tag(SessionId, "test");
+ for (JvmMetricsInfo info : JvmMetricsInfo.values()) {
+ if (info.name().equals("GcTimePercentage")) {
+ verify(rb).addCounter(eq(info), anyInt());
+ }
}
}
@@ -120,4 +149,55 @@ public class TestJvmMetrics {
}
}
+ @Test
+ public void testGcTimeMonitor() {
+ class Alerter implements GcTimeMonitor.GcTimeAlertHandler {
+ private volatile int numAlerts;
+ private volatile int maxGcTimePercentage;
+ @Override
+ public void alert(GcTimeMonitor.GcData gcData) {
+ numAlerts++;
+ if (gcData.getGcTimePercentage() > maxGcTimePercentage) {
+ maxGcTimePercentage = gcData.getGcTimePercentage();
+ }
+ }
+ }
+ Alerter alerter = new Alerter();
+
+ int alertGcPerc = 10; // Alerter should be called if GC takes >= 10%
+ gcTimeMonitor = new GcTimeMonitor(60*1000, 100, alertGcPerc, alerter);
+ gcTimeMonitor.start();
+
+ int maxGcTimePercentage = 0;
+ long gcCount = 0;
+
+ // Generate a lot of garbage for some time and verify that the monitor
+ // reports at least some percentage of time in GC pauses, and that the
+ // alerter is invoked at least once.
+
+ List<String> garbageStrings = new ArrayList<>();
+
+ long startTime = System.currentTimeMillis();
+ // Run this for at least 1 sec for our monitor to collect enough data
+ while (System.currentTimeMillis() - startTime < 1000) {
+ for (int j = 0; j < 100000; j++) {
+ garbageStrings.add(
+ "Long string prefix just to fill memory with garbage " + j);
+ }
+ garbageStrings.clear();
+ System.gc();
+
+ GcTimeMonitor.GcData gcData = gcTimeMonitor.getLatestGcData();
+ int gcTimePercentage = gcData.getGcTimePercentage();
+ if (gcTimePercentage > maxGcTimePercentage) {
+ maxGcTimePercentage = gcTimePercentage;
+ }
+ gcCount = gcData.getAccumulatedGcCount();
+ }
+
+ Assert.assertTrue(maxGcTimePercentage > 0);
+ Assert.assertTrue(gcCount > 0);
+ Assert.assertTrue(alerter.numAlerts > 0);
+ Assert.assertTrue(alerter.maxGcTimePercentage >= alertGcPerc);
+ }
}
---------------------------------------------------------------------
To unsubscribe, e-mail: common-commits-unsubscribe@hadoop.apache.org
For additional commands, e-mail: common-commits-help@hadoop.apache.org