HIVE-14070: hive.tez.exec.print.summary=true returns wrong performanc…

…e numbers on HS2 (Pengcheng Xiong, reviewed by Thejas M Nair, Sergey Shelukhin, Ashutosh Chauhan)
apache · Jun 25, 2016 · 4f3c27c · 4f3c27c
1 parent 0415845
commit 4f3c27c
Show file tree

Hide file tree

Showing 4 changed files with 16 additions and 8 deletions.
diff --git a/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java b/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
@@ -62,7 +62,6 @@ public class PerfLogger {
   public static final String POST_HOOK = "PostHook.";
   public static final String FAILURE_HOOK = "FailureHook.";
   public static final String DRIVER_RUN = "Driver.run";
-  public static final String TIME_TO_SUBMIT = "TimeToSubmit";
   public static final String TEZ_COMPILER = "TezCompiler";
   public static final String TEZ_SUBMIT_TO_RUNNING = "TezSubmitToRunningDag";
   public static final String TEZ_BUILD_DAG = "TezBuildDag";
@@ -118,6 +117,10 @@ public static PerfLogger getPerfLogger(HiveConf conf, boolean resetPerfLogger) {
     return result;
   }
 
+  public static void setPerfLogger(PerfLogger resetPerfLogger) {
+    perfLogger.set(resetPerfLogger);
+  }
+
   /**
    * Call this function when you start to measure time spent by a piece of code.
    * @param callerName the logging object to be used.

diff --git a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
@@ -337,7 +337,8 @@ public int compile(String command) {
    * @return 0 for ok
    */
   public int compile(String command, boolean resetTaskIds) {
-    PerfLogger perfLogger = SessionState.getPerfLogger();
+    PerfLogger perfLogger = SessionState.getPerfLogger(true);
+    perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.DRIVER_RUN);
     perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.COMPILE);
 
     command = new VariableSubstitution(new HiveVariableSource() {
@@ -1243,18 +1244,20 @@ private CommandProcessorResponse runInternal(String command, boolean alreadyComp
       return createProcessorResponse(12);
     }
 
-    // Reset the perf logger
-    PerfLogger perfLogger = SessionState.getPerfLogger(true);
-    perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.DRIVER_RUN);
-    perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.TIME_TO_SUBMIT);
+    PerfLogger perfLogger = null;
 
     int ret;
     if (!alreadyCompiled) {
+      // compile internal will automatically reset the perf logger
       ret = compileInternal(command);
+      // then we continue to use this perf logger
+      perfLogger = SessionState.getPerfLogger();
       if (ret != 0) {
         return createProcessorResponse(ret);
       }
     } else {
+      // reuse existing perf logger.
+      perfLogger = SessionState.getPerfLogger();
       // Since we're reusing the compiled plan, we need to update its start time for current run
       plan.setQueryStartTime(perfLogger.getStartTime(PerfLogger.DRIVER_RUN));
     }
@@ -1551,7 +1554,6 @@ public int execute() throws CommandNeedRetryException {
         driverCxt.addToRunnable(tsk);
       }
 
-      perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.TIME_TO_SUBMIT);
       perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.RUN_TASKS);
       // Loop while you either have tasks running, or tasks queued up
       while (!destroyed && driverCxt.isRunning()) {

diff --git a/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezJobMonitor.java b/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezJobMonitor.java
@@ -444,7 +444,7 @@ private void printQueryExecutionBreakDown() {
 
     // parse, analyze, optimize and compile
     long compile = perfLogger.getEndTime(PerfLogger.COMPILE) -
-        perfLogger.getStartTime(PerfLogger.DRIVER_RUN);
+        perfLogger.getStartTime(PerfLogger.COMPILE);
     console.printInfo(String.format(OPERATION_SUMMARY, "Compile Query",
         secondsFormat.format(compile / 1000.0) + "s"));
 

diff --git a/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java b/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java
@@ -54,6 +54,7 @@
 import org.apache.hadoop.hive.ql.exec.ExplainTask;
 import org.apache.hadoop.hive.ql.exec.FetchTask;
 import org.apache.hadoop.hive.ql.exec.Task;
+import org.apache.hadoop.hive.ql.log.PerfLogger;
 import org.apache.hadoop.hive.ql.metadata.Hive;
 import org.apache.hadoop.hive.ql.processors.CommandProcessorResponse;
 import org.apache.hadoop.hive.ql.session.OperationLog;
@@ -282,6 +283,7 @@ public void runInternal() throws HiveSQLException {
       // ThreadLocal Hive object needs to be set in background thread.
       // The metastore client in Hive is associated with right user.
       final Hive parentHive = parentSession.getSessionHive();
+      final PerfLogger parentPerfLogger = SessionState.getPerfLogger();
       // Current UGI will get used by metastore when metsatore is in embedded mode
       // So this needs to get passed to the new background thread
       final UserGroupInformation currentUGI = getCurrentUGI();
@@ -295,6 +297,7 @@ public void run() {
             public Object run() throws HiveSQLException {
               Hive.set(parentHive);
               SessionState.setCurrentSessionState(parentSessionState);
+              PerfLogger.setPerfLogger(parentPerfLogger);
               // Set current OperationLog in this async thread for keeping on saving query log.
               registerCurrentOperationLog();
               registerLoggingContext();