You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hive.apache.org by vi...@apache.org on 2018/05/12 18:29:50 UTC
hive git commit: HIVE-19510 : Add performance metric to find the
total time spend in rsync (Vihang Karajgaonkar)
Repository: hive
Updated Branches:
refs/heads/HIVE-19429 154a68655 -> 5b694b7be
HIVE-19510 : Add performance metric to find the total time spend in rsync (Vihang Karajgaonkar)
Project: http://git-wip-us.apache.org/repos/asf/hive/repo
Commit: http://git-wip-us.apache.org/repos/asf/hive/commit/5b694b7b
Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/5b694b7b
Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/5b694b7b
Branch: refs/heads/HIVE-19429
Commit: 5b694b7be66e6abc12abecc8c5be437ce39d4d25
Parents: 154a686
Author: Vihang Karajgaonkar <vi...@cloudera.com>
Authored: Sat May 12 11:12:49 2018 -0700
Committer: Vihang Karajgaonkar <vi...@cloudera.com>
Committed: Sat May 12 11:28:40 2018 -0700
----------------------------------------------------------------------
.../hive/ptest/execution/ExecutionPhase.java | 14 ++++++++++
.../hive/ptest/execution/HostExecutor.java | 8 ++++++
.../hive/ptest/execution/LocalCommand.java | 9 +++++++
.../org/apache/hive/ptest/execution/PTest.java | 13 +++++++++-
.../org/apache/hive/ptest/execution/Phase.java | 18 +++++++++++++
.../hive/ptest/execution/ssh/RSyncCommand.java | 13 +++++++++-
.../execution/ssh/RSyncCommandExecutor.java | 1 +
.../hive/ptest/execution/ssh/RSyncResult.java | 5 +++-
.../execution/MockRSyncCommandExecutor.java | 4 +++
.../ptest/execution/TestExecutionPhase.java | 27 ++++++++++++++++++++
10 files changed, 109 insertions(+), 3 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ExecutionPhase.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ExecutionPhase.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ExecutionPhase.java
index 2015187..7ab98f6 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ExecutionPhase.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ExecutionPhase.java
@@ -22,8 +22,10 @@ import java.io.File;
import java.io.IOException;
import java.util.Collection;
import java.util.Collections;
+import java.util.HashMap;
import java.util.HashSet;
import java.util.List;
+import java.util.Map;
import java.util.Set;
import java.util.concurrent.BlockingQueue;
import java.util.concurrent.LinkedBlockingQueue;
@@ -102,6 +104,7 @@ public class ExecutionPhase extends Phase {
try {
int expectedNumHosts = hostExecutors.size();
initalizeHosts();
+ resetPerfMetrics();
do {
replaceBadHosts(expectedNumHosts);
List<ListenableFuture<Void>> results = Lists.newArrayList();
@@ -145,10 +148,21 @@ public class ExecutionPhase extends Phase {
}
} finally {
long elapsed = System.currentTimeMillis() - start;
+ addAggregatePerfMetrics();
logger.info("PERF: exec phase " +
TimeUnit.MINUTES.convert(elapsed, TimeUnit.MILLISECONDS) + " minutes");
}
}
+
+ public static final String TOTAL_RSYNC_TIME = "TotalRsyncElapsedTime";
+ private void addAggregatePerfMetrics() {
+ long totalRsycTime = 0L;
+ for (HostExecutor hostExecutor : ImmutableList.copyOf(hostExecutors)) {
+ totalRsycTime += hostExecutor.getTotalRsyncTimeInMs();
+ }
+ addPerfMetric(TOTAL_RSYNC_TIME, totalRsycTime);
+ }
+
private void replaceBadHosts(int expectedNumHosts)
throws Exception {
Set<Host> goodHosts = Sets.newHashSet();
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/HostExecutor.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/HostExecutor.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/HostExecutor.java
index 3a4fa7f..47347eb 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/HostExecutor.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/HostExecutor.java
@@ -28,6 +28,7 @@ import java.util.concurrent.BlockingQueue;
import java.util.concurrent.Callable;
import java.util.concurrent.CopyOnWriteArrayList;
import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
import com.google.common.base.Stopwatch;
import org.apache.commons.lang.StringUtils;
@@ -70,6 +71,7 @@ class HostExecutor {
private volatile boolean mShutdown;
private int numParallelBatchesProcessed = 0;
private int numIsolatedBatchesProcessed = 0;
+ private AtomicLong totalElapsedTimeInRsync = new AtomicLong(0L);
HostExecutor(Host host, String privateKey, ListeningExecutorService executor,
SSHCommandExecutor sshCommandExecutor,
@@ -139,6 +141,10 @@ class HostExecutor {
boolean isShutdown() {
return mShutdown;
}
+
+ long getTotalRsyncTimeInMs() {
+ return totalElapsedTimeInRsync.get();
+ }
/**
* Executes parallel test until the parallel work queue is empty. Then
* executes the isolated tests on the host. During each phase if a
@@ -311,6 +317,7 @@ class HostExecutor {
if(result.getException() != null || result.getExitCode() != 0) {
throw new SSHExecutionException(result);
}
+ totalElapsedTimeInRsync.getAndAdd(result.getElapsedTimeInMs());
return result;
}
/**
@@ -380,6 +387,7 @@ class HostExecutor {
if(result.getException() != null || result.getExitCode() != Constants.EXIT_CODE_SUCCESS) {
throw new SSHExecutionException(result);
}
+ totalElapsedTimeInRsync.getAndAdd(result.getElapsedTimeInMs());
return result;
}
/**
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/LocalCommand.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/LocalCommand.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/LocalCommand.java
index b57320d..cf9606e 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/LocalCommand.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/LocalCommand.java
@@ -37,6 +37,7 @@ public class LocalCommand {
private final StreamReader streamReader;
private Integer exitCode;
private final int commandId;
+ private long elapsedTimeInMs;
private final Stopwatch stopwatch = Stopwatch.createUnstarted();
public LocalCommand(Logger logger, OutputPolicy outputPolicy, String command) throws IOException {
@@ -58,12 +59,20 @@ public class LocalCommand {
}
}
+ public long getElapsedTimeInMs() throws InterruptedException {
+ synchronized (process) {
+ awaitProcessCompletion();
+ return elapsedTimeInMs;
+ }
+ }
+
private void awaitProcessCompletion() throws InterruptedException {
synchronized (process) {
if (exitCode == null) {
exitCode = process.waitFor();
if (stopwatch.isRunning()) {
stopwatch.stop();
+ this.elapsedTimeInMs = stopwatch.elapsed(TimeUnit.MILLISECONDS);
logger.info("Finished LocalCommandId={}. ElapsedTime(ms)={}", commandId,
stopwatch.elapsed(
TimeUnit.MILLISECONDS));
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PTest.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PTest.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PTest.java
index 8df5162..2868ff0 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PTest.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PTest.java
@@ -26,8 +26,10 @@ import java.util.Collections;
import java.util.HashSet;
import java.util.List;
import java.util.Map;
+import java.util.Map.Entry;
import java.util.Set;
import java.util.SortedSet;
+import java.util.TreeMap;
import java.util.TreeSet;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.CopyOnWriteArrayList;
@@ -74,6 +76,7 @@ public class PTest {
.getLogger(PTest.class);
+ // dummy patch
private final TestConfiguration mConfiguration;
private final ListeningExecutorService mExecutor;
private final Set<String> mAddedTests;
@@ -182,6 +185,14 @@ public class PTest {
} finally {
long elapsedTime = TimeUnit.MINUTES.convert((System.currentTimeMillis() - start),
TimeUnit.MILLISECONDS);
+ Map<String, Long> perfMetrics = phase.getPerfMetrics();
+ if (!perfMetrics.isEmpty()) {
+ mLogger.info("Adding perf metrics for " + phase.getClass().getSimpleName() + " phase");
+ for (Entry<String, Long> perfEntry : perfMetrics.entrySet()) {
+ elapsedTimes.put(phase.getClass().getSimpleName() + "." + perfEntry.getKey(),
+ TimeUnit.MINUTES.convert(perfEntry.getValue(), TimeUnit.MILLISECONDS));
+ }
+ }
elapsedTimes.put(phase.getClass().getSimpleName(), elapsedTime);
}
}
@@ -223,7 +234,7 @@ public class PTest {
}
mLogger.info("Executed " + mExecutedTests.size() + " tests");
for(Map.Entry<String, Long> entry : elapsedTimes.entrySet()) {
- mLogger.info(String.format("PERF: Phase %s took %d minutes", entry.getKey(), entry.getValue()));
+ mLogger.info(String.format("PERF: %s took %d minutes", entry.getKey(), entry.getValue()));
}
publishJiraComment(error, messages, failedTests, mAddedTests);
if(error || !mFailedTests.isEmpty()) {
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/Phase.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/Phase.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/Phase.java
index c049d65..34c66ce 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/Phase.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/Phase.java
@@ -20,10 +20,14 @@ package org.apache.hive.ptest.execution;
import java.io.IOException;
import java.util.List;
+import java.util.Map;
+import java.util.TreeMap;
import java.util.concurrent.Callable;
+import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
+import com.google.common.collect.Maps;
import org.apache.hive.ptest.execution.LocalCommand.CollectLogPolicy;
import org.apache.hive.ptest.execution.ssh.NonZeroExitCodeException;
import org.apache.hive.ptest.execution.ssh.RemoteCommandResult;
@@ -44,6 +48,7 @@ public abstract class Phase {
private final LocalCommandFactory localCommandFactory;
private final ImmutableMap<String, String> templateDefaults;
protected final Logger logger;
+ private Map<String, Long> perfMetrics;
public Phase(List<HostExecutor> hostExecutors,
LocalCommandFactory localCommandFactory,
@@ -53,6 +58,7 @@ public abstract class Phase {
this.localCommandFactory = localCommandFactory;
this.templateDefaults = templateDefaults;
this.logger = logger;
+ this.perfMetrics = new ConcurrentHashMap<>();
}
public abstract void execute() throws Throwable;
@@ -186,4 +192,16 @@ public abstract class Phase {
protected ImmutableMap<String, String> getTemplateDefaults() {
return templateDefaults;
}
+
+ public Map<String, Long> getPerfMetrics() {
+ return ImmutableMap.copyOf(perfMetrics);
+ }
+
+ public void addPerfMetric(final String metricKey, long value) {
+ perfMetrics.put(metricKey, Long.valueOf(value));
+ }
+
+ public void resetPerfMetrics() {
+ perfMetrics = new ConcurrentHashMap<>();
+ }
}
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommand.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommand.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommand.java
index fbb1e79..cadf209 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommand.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommand.java
@@ -22,6 +22,7 @@ public class RSyncCommand extends AbstractSSHCommand<RSyncResult> {
private final RSyncCommandExecutor executor;
private final String localFile;
private final String remoteFile;
+ private long elapsedTimeInMs;
private RSyncCommand.Type type;
public RSyncCommand(RSyncCommandExecutor executor, String privateKey,
String user, String host, int instance,
@@ -35,17 +36,23 @@ public class RSyncCommand extends AbstractSSHCommand<RSyncResult> {
public RSyncCommand.Type getType() {
return type;
}
+
+ public void setElapsedTimeInMs(long timeInMs) {
+ this.elapsedTimeInMs = timeInMs;
+ }
+
public String getLocalFile() {
return localFile;
}
public String getRemoteFile() {
return remoteFile;
}
+
@Override
public RSyncResult call() {
executor.execute(this);
return new RSyncResult(getUser(), getHost(), getInstance(), getLocalFile(), getRemoteFile(),
- getExitCode(), getException(), getOutput());
+ getExitCode(), getException(), getOutput(), getElapsedTimeInMs());
}
@Override
@@ -55,6 +62,10 @@ public class RSyncCommand extends AbstractSSHCommand<RSyncResult> {
+ getHost() + ", getInstance()=" + getInstance() + "]";
}
+ public long getElapsedTimeInMs() {
+ return elapsedTimeInMs;
+ }
+
public static enum Type {
FROM_LOCAL(),
TO_LOCAL(),
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommandExecutor.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommandExecutor.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommandExecutor.java
index cd7bcf9..af06f20 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommandExecutor.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncCommandExecutor.java
@@ -93,6 +93,7 @@ public class RSyncCommandExecutor {
}
} while (!mShutdown && retry); // an error occurred, re-try
command.setExitCode(cmd.getExitCode());
+ command.setElapsedTimeInMs(cmd.getElapsedTimeInMs());
} catch (IOException e) {
command.setException(e);
} catch (InterruptedException e) {
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncResult.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncResult.java b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncResult.java
index ae6bac8..12a0435 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncResult.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/ssh/RSyncResult.java
@@ -21,12 +21,14 @@ package org.apache.hive.ptest.execution.ssh;
public class RSyncResult extends AbstractSSHResult {
private final String localFile;
private final String remoteFile;
+ private final long elapsedTimeInMs;
public RSyncResult(String user, String host, int instance,
String localFile, String remoteFile, int exitCode,
- Exception exception, String output) {
+ Exception exception, String output, long elapsedTimeInMs) {
super(user, host, instance, exitCode, exception, output);
this.localFile = localFile;
this.remoteFile = remoteFile;
+ this.elapsedTimeInMs = elapsedTimeInMs;
}
public String getLocalFile() {
return localFile;
@@ -34,6 +36,7 @@ public class RSyncResult extends AbstractSSHResult {
public String getRemoteFile() {
return remoteFile;
}
+ public long getElapsedTimeInMs() { return elapsedTimeInMs; }
@Override
public String toString() {
return "RSyncResult [localFile=" + localFile + ", remoteFile="
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/MockRSyncCommandExecutor.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/MockRSyncCommandExecutor.java b/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/MockRSyncCommandExecutor.java
index 3906435..fd4749e 100644
--- a/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/MockRSyncCommandExecutor.java
+++ b/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/MockRSyncCommandExecutor.java
@@ -18,10 +18,12 @@
*/
package org.apache.hive.ptest.execution;
+import java.security.SecureRandom;
import java.util.LinkedList;
import java.util.List;
import java.util.Map;
import java.util.Queue;
+import java.util.Random;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicInteger;
@@ -68,6 +70,8 @@ public class MockRSyncCommandExecutor extends RSyncCommandExecutor {
matchCount.incrementAndGet();
command.setExitCode(queue.remove());
}
+ //simulating dummy rsync delay of 17 msec
+ command.setElapsedTimeInMs(17L);
}
public int getMatchCount() {
http://git-wip-us.apache.org/repos/asf/hive/blob/5b694b7b/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/TestExecutionPhase.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/TestExecutionPhase.java b/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/TestExecutionPhase.java
index 24c811e..c32ce10 100644
--- a/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/TestExecutionPhase.java
+++ b/testutils/ptest2/src/test/java/org/apache/hive/ptest/execution/TestExecutionPhase.java
@@ -150,6 +150,33 @@ public class TestExecutionPhase extends AbstractTestPhase {
Assert.assertEquals(Sets.newHashSet("SomeTest." + QFILENAME + " (batchId=1)"), failedTests);
}
+ @Test
+ public void testPerfMetrics() throws Throwable {
+ //when test is successful
+ setupUnitTest();
+ copyTestOutput("SomeTest-success.xml", succeededLogDir, testBatch.getName());
+ Phase phase = getPhase();
+ phase.execute();
+ Assert.assertNotNull("Perf metrics should have been initialized", phase.getPerfMetrics());
+ Assert.assertNotNull(ExecutionPhase.TOTAL_RSYNC_TIME + " should have been initialized",
+ phase.getPerfMetrics().get(ExecutionPhase.TOTAL_RSYNC_TIME));
+ Assert.assertTrue("Total Rsync Elapsed time should have been greater than 0",
+ phase.getPerfMetrics().get(ExecutionPhase.TOTAL_RSYNC_TIME) > 0);
+
+ //when test fails
+ setupUnitTest();
+ sshCommandExecutor.putFailure("bash " + LOCAL_DIR + "/" + HOST + "-" + USER +
+ "-0/scratch/hiveptest-" + testBatch.getBatchId() + "_" + DRIVER + ".sh", 1);
+ copyTestOutput("SomeTest-failure.xml", failedLogDir, testBatch.getName());
+ phase = getPhase();
+ phase.execute();
+ Assert.assertNotNull("Perf metrics should have been initialized", phase.getPerfMetrics());
+ Assert.assertNotNull(ExecutionPhase.TOTAL_RSYNC_TIME + " should have been initialized",
+ phase.getPerfMetrics().get(ExecutionPhase.TOTAL_RSYNC_TIME));
+ Assert.assertTrue("Total Rsync Elapsed time should have been greater than 0",
+ phase.getPerfMetrics().get(ExecutionPhase.TOTAL_RSYNC_TIME) > 0);
+ }
+
@Test(timeout = 20000)
public void testTimedOutUnitTest() throws Throwable {
setupUnitTest(3);