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 <[email protected]> Authored: Sat May 12 11:12:49 2018 -0700 Committer: Vihang Karajgaonkar <[email protected]> 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);
