hive-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From ss...@apache.org
Subject hive git commit: HIVE-13507. Improved logging for ptest. (Siddharth Seth, reviewed by Thejas M Nair)
Date Mon, 18 Apr 2016 18:06:38 GMT
Repository: hive
Updated Branches:
  refs/heads/master c3fee305e -> fcc2e7951


HIVE-13507. Improved logging for ptest. (Siddharth Seth, reviewed by Thejas M Nair)


Project: http://git-wip-us.apache.org/repos/asf/hive/repo
Commit: http://git-wip-us.apache.org/repos/asf/hive/commit/fcc2e795
Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/fcc2e795
Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/fcc2e795

Branch: refs/heads/master
Commit: fcc2e79511bb1a0db70f4a17ede6ade5e73b1f42
Parents: c3fee30
Author: Siddharth Seth <sseth@apache.org>
Authored: Mon Apr 18 11:05:59 2016 -0700
Committer: Siddharth Seth <sseth@apache.org>
Committed: Mon Apr 18 11:05:59 2016 -0700

----------------------------------------------------------------------
 .../hive/ptest/execution/ExecutionPhase.java    |  2 +
 .../hive/ptest/execution/HostExecutor.java      | 48 ++++++++++++++++++--
 .../hive/ptest/execution/LocalCommand.java      | 18 +++++++-
 .../apache/hive/ptest/execution/PrepPhase.java  |  1 +
 .../apache/hive/ptest/execution/conf/Host.java  |  3 ++
 5 files changed, 65 insertions(+), 7 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/hive/blob/fcc2e795/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 3026ea0..6063afc 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
@@ -86,6 +86,8 @@ public class ExecutionPhase extends Phase {
         isolatedWorkQueue.add(batch);
       }
     }
+    logger.info("ParallelWorkQueueSize={}, IsolatedWorkQueueSize={}", parallelWorkQueue.size(),
+        isolatedWorkQueue.size());
     try {
       int expectedNumHosts = hostExecutors.size();
       initalizeHosts();

http://git-wip-us.apache.org/repos/asf/hive/blob/fcc2e795/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 b05d2c2..735b261 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
@@ -29,6 +29,7 @@ import java.util.concurrent.Callable;
 import java.util.concurrent.CopyOnWriteArrayList;
 import java.util.concurrent.TimeUnit;
 
+import com.google.common.base.Stopwatch;
 import org.apache.hive.ptest.execution.conf.Host;
 import org.apache.hive.ptest.execution.conf.TestBatch;
 import org.apache.hive.ptest.execution.ssh.RSyncCommand;
@@ -65,6 +66,8 @@ class HostExecutor {
   private final File mFailedTestLogDir;
   private final long mNumPollSeconds;
   private volatile boolean mShutdown;
+  private int numParallelBatchesProcessed = 0;
+  private int numIsolatedBatchesProcessed = 0;
   
   HostExecutor(Host host, String privateKey, ListeningExecutorService executor,
       SSHCommandExecutor sshCommandExecutor,
@@ -100,7 +103,18 @@ class HostExecutor {
     return mExecutor.submit(new Callable<Void>() {
       @Override
       public Void call() throws Exception {
-        executeTests(parallelWorkQueue, isolatedWorkQueue, failedTestResults);
+        Stopwatch stopwatch = Stopwatch.createStarted();
+        mLogger.info("Starting SubmitTests on host {}", getHost());
+        try {
+          executeTests(parallelWorkQueue, isolatedWorkQueue, failedTestResults);
+        } finally {
+          stopwatch.stop();
+          mLogger.info("Finishing submitTests on host: {}. ElapsedTime(seconds)={}," +
+              " NumParallelBatchesProcessed={}, NumIsolatedBatchesProcessed={}",
+              new Object[]{getHost().toString(),
+                  stopwatch.elapsed(TimeUnit.SECONDS), numParallelBatchesProcessed,
+                  numIsolatedBatchesProcessed});
+        }
         return null;
       }
 
@@ -143,6 +157,7 @@ class HostExecutor {
         @Override
         public Void call() throws Exception {
           TestBatch batch = null;
+          Stopwatch sw = Stopwatch.createUnstarted();
           try {
             do {
               batch = parallelWorkQueue.poll(mNumPollSeconds, TimeUnit.SECONDS);
@@ -151,8 +166,16 @@ class HostExecutor {
                 return null;
               }
               if(batch != null) {
-                if(!executeTestBatch(drone, batch, failedTestResults)) {
-                  failedTestResults.add(batch);
+                numParallelBatchesProcessed++;
+                sw.reset().start();
+                try {
+                  if (!executeTestBatch(drone, batch, failedTestResults)) {
+                    failedTestResults.add(batch);
+                  }
+                } finally {
+                  sw.stop();
+                  mLogger.info("Finished processing parallel batch [{}] on host {}. ElapsedTime(seconds)={}",
+                      new Object[]{batch.getName(), getHost().toShortString(), sw.elapsed(TimeUnit.SECONDS)});
                 }
               }
             } while(!mShutdown && !parallelWorkQueue.isEmpty());
@@ -176,12 +199,22 @@ class HostExecutor {
     mLogger.info("Starting isolated execution on " + mHost.getName());
     for(Drone drone : ImmutableList.copyOf(mDrones)) {
       TestBatch batch = null;
+      Stopwatch sw = Stopwatch.createUnstarted();
       try {
         do {
+
           batch = isolatedWorkQueue.poll(mNumPollSeconds, TimeUnit.SECONDS);
           if(batch != null) {
-            if(!executeTestBatch(drone, batch, failedTestResults)) {
-              failedTestResults.add(batch);
+            numIsolatedBatchesProcessed++;
+            sw.reset().start();
+            try {
+              if (!executeTestBatch(drone, batch, failedTestResults)) {
+                failedTestResults.add(batch);
+              }
+            } finally {
+              sw.stop();
+              mLogger.info("Finished processing isolated batch [{}] on host {}. ElapsedTime(seconds)={}",
+                  new Object[]{batch.getName(), getHost().toShortString(), sw.elapsed(TimeUnit.SECONDS)});
             }
           }
         } while(!mShutdown && !isolatedWorkQueue.isEmpty());
@@ -215,10 +248,15 @@ class HostExecutor {
     Templates.writeTemplateResult("batch-exec.vm", script, templateVariables);
     copyToDroneFromLocal(drone, script.getAbsolutePath(), "$localDir/$instanceName/scratch/"
+ scriptName);
     script.delete();
+    Stopwatch sw = Stopwatch.createStarted();
     mLogger.info(drone + " executing " + batch + " with " + command);
     RemoteCommandResult sshResult = new SSHCommand(mSSHCommandExecutor, drone.getPrivateKey(),
drone.getUser(),
         drone.getHost(), drone.getInstance(), command, true).
         call();
+    sw.stop();
+    mLogger.info("Completed executing tests for batch [{}] on host {}. ElapsedTime(seconds)={}",
+        new Object[]{batch.getName(),
+            getHost().toShortString(), sw.elapsed(TimeUnit.SECONDS)});
     File batchLogDir = null;
     if(sshResult.getExitCode() == Constants.EXIT_CODE_UNKNOWN) {
       throw new AbortDroneException("Drone " + drone.toString() + " exited with " +

http://git-wip-us.apache.org/repos/asf/hive/blob/fcc2e795/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 ec99656..8e2c5c7 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
@@ -22,17 +22,28 @@ import java.io.BufferedReader;
 import java.io.IOException;
 import java.io.InputStream;
 import java.io.InputStreamReader;
+import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicInteger;
 
+import com.google.common.base.Stopwatch;
 import org.slf4j.Logger;
 
 public class LocalCommand {
 
+  private static final AtomicInteger localCommandCounter = new AtomicInteger(0);
+
+  private final Logger logger;
   private final Process process;
   private final StreamReader streamReader;
   private Integer exitCode;
+  private final int commandId;
+  private final Stopwatch stopwatch = Stopwatch.createUnstarted();
 
   public LocalCommand(Logger logger, OutputPolicy outputPolicy, String command) throws IOException
{
-    logger.info("Starting " + command);
+    this.commandId = localCommandCounter.incrementAndGet();
+    this.logger = logger;
+    logger.info("Starting LocalCommandId={}: {}" + commandId, command);
+    stopwatch.start();
     process = new ProcessBuilder().command(new String[] {"bash", "-c", command}).redirectErrorStream(true).start();
     streamReader = new StreamReader(outputPolicy, process.getInputStream());
     streamReader.setName("StreamReader-[" + command + "]");
@@ -45,10 +56,13 @@ public class LocalCommand {
       if(exitCode == null) {
         exitCode = process.waitFor();
       }
+      stopwatch.stop();
+      logger.info("Finished LocalCommandId={}. ElapsedTime(seconds)={}", commandId, stopwatch.elapsed(
+          TimeUnit.SECONDS));
       return exitCode;
     }
   }
-  
+
   public void kill() {
     synchronized (process) {
       process.destroy();

http://git-wip-us.apache.org/repos/asf/hive/blob/fcc2e795/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PrepPhase.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PrepPhase.java
b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PrepPhase.java
index 825f0c0..8fef413 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PrepPhase.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/PrepPhase.java
@@ -62,6 +62,7 @@ public class PrepPhase extends Phase {
     // source prep
     start = System.currentTimeMillis();
     File sourcePrepScript = new File(mScratchDir, "source-prep.sh");
+    logger.info("Writing {} from template", sourcePrepScript);
     Templates.writeTemplateResult("source-prep.vm", sourcePrepScript, getTemplateDefaults());
     execLocally("bash " + sourcePrepScript.getPath());
     logger.debug("Deleting " + sourcePrepScript + ": " + sourcePrepScript.delete());

http://git-wip-us.apache.org/repos/asf/hive/blob/fcc2e795/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/conf/Host.java
----------------------------------------------------------------------
diff --git a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/conf/Host.java
b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/conf/Host.java
index c1216c1..a56824c 100644
--- a/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/conf/Host.java
+++ b/testutils/ptest2/src/main/java/org/apache/hive/ptest/execution/conf/Host.java
@@ -47,6 +47,9 @@ public class Host {
   public String[] getLocalDirectories() {
     return localDirectories;
   }
+  public String toShortString() {
+    return name;
+  }
   @Override
   public String toString() {
     return "Host [name=" + name + ", user=" + user + ", threads=" + threads


Mime
View raw message