hive-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From prasan...@apache.org
Subject hive git commit: HIVE-13226: Improve tez print summary to print query execution breakdown (Prasanth Jayachandran reviewed by Gopal V)
Date Tue, 15 Mar 2016 18:17:18 GMT
Repository: hive
Updated Branches:
  refs/heads/master d5b1adbb6 -> 812820086


HIVE-13226: Improve tez print summary to print query execution breakdown (Prasanth Jayachandran
reviewed by Gopal V)


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

Branch: refs/heads/master
Commit: 812820086098f238214adee26d65c7cb617056d3
Parents: d5b1adb
Author: Prasanth Jayachandran <j.prasanth.j@gmail.com>
Authored: Tue Mar 15 13:13:29 2016 -0500
Committer: Prasanth Jayachandran <j.prasanth.j@gmail.com>
Committed: Tue Mar 15 13:13:29 2016 -0500

----------------------------------------------------------------------
 .../llap/io/encoded/OrcEncodedDataReader.java   |   2 +-
 .../hadoop/hive/ql/exec/tez/TezJobMonitor.java  | 142 +++++++++++--------
 2 files changed, 80 insertions(+), 64 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/hive/blob/81282008/llap-server/src/java/org/apache/hadoop/hive/llap/io/encoded/OrcEncodedDataReader.java
----------------------------------------------------------------------
diff --git a/llap-server/src/java/org/apache/hadoop/hive/llap/io/encoded/OrcEncodedDataReader.java
b/llap-server/src/java/org/apache/hadoop/hive/llap/io/encoded/OrcEncodedDataReader.java
index bcee56b..8111c6d 100644
--- a/llap-server/src/java/org/apache/hadoop/hive/llap/io/encoded/OrcEncodedDataReader.java
+++ b/llap-server/src/java/org/apache/hadoop/hive/llap/io/encoded/OrcEncodedDataReader.java
@@ -771,7 +771,7 @@ public class OrcEncodedDataReader extends CallableWithNdc<Void>
     } else if (!isNone) {
       count = rgCount;
     }
-    counters.setCounter(LlapIOCounters.SELECTED_ROWGROUPS, count);
+    counters.incrCounter(LlapIOCounters.SELECTED_ROWGROUPS, count);
   }
 
 

http://git-wip-us.apache.org/repos/asf/hive/blob/81282008/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezJobMonitor.java
----------------------------------------------------------------------
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
index 418a03e..67f9da8 100644
--- 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
@@ -73,7 +73,7 @@ public class TezJobMonitor {
   private static final int COLUMN_1_WIDTH = 16;
   private static final int SEPARATOR_WIDTH = InPlaceUpdates.MIN_TERMINAL_WIDTH;
   private static final String SEPARATOR = new String(new char[SEPARATOR_WIDTH]).replace("\0",
"-");
-  private static final String PREP_SUMMARY_HEADER = "DAG Preparation Summary";
+  private static final String QUERY_EXEC_SUMMARY_HEADER = "Query Execution Summary";
   private static final String TASK_SUMMARY_HEADER = "Task Execution Summary";
   private static final String LLAP_IO_SUMMARY_HEADER = "LLAP IO Summary";
 
@@ -95,9 +95,11 @@ public class TezJobMonitor {
   private static final String LLAP_SUMMARY_HEADER = String.format(LLAP_SUMMARY_HEADER_FORMAT,
       "VERTICES", "ROWGROUPS", "META_HIT", "META_MISS", "DATA_HIT", "DATA_MISS",
       "ALLOCATION", "USED", "TOTAL_IO");
-  private static final String TOTAL_PREP_TIME = "TotalPrepTime";
-  private static final String METHOD = "METHOD";
-  private static final String DURATION = "DURATION(ms)";
+
+  // Methods summary
+  private static final String OPERATION_SUMMARY = "%-35s %9s";
+  private static final String OPERATION = "OPERATION";
+  private static final String DURATION = "DURATION";
 
   // in-place progress update related variables
   private int lines;
@@ -214,6 +216,7 @@ public class TezJobMonitor {
 
     boolean running = false;
     boolean done = false;
+    boolean success = false;
     int failedCounter = 0;
     int rc = 0;
     DAGStatus.State lastState = null;
@@ -231,12 +234,12 @@ public class TezJobMonitor {
     console.printInfo("\n");
     perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.TEZ_RUN_DAG);
     perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.TEZ_SUBMIT_TO_RUNNING);
-
+    Map<String, Progress> progressMap = null;
     while (true) {
 
       try {
         status = dagClient.getDAGStatus(opts, checkInterval);
-        Map<String, Progress> progressMap = status.getVertexProgress();
+        progressMap = status.getVertexProgress();
         DAGStatus.State state = status.getState();
 
         if (state != lastState || state == RUNNING) {
@@ -277,35 +280,7 @@ public class TezJobMonitor {
             } else {
               lastReport = printStatus(progressMap, lastReport, console);
             }
-
-            /* Profile info is collected anyways, isProfileEnabled
-             * decides if it gets printed or not
-             */
-            if (isProfileEnabled) {
-
-              double duration = (System.currentTimeMillis() - startTime) / 1000.0;
-              console.printInfo("Status: DAG finished successfully in "
-                  + String.format("%.2f seconds", duration));
-              console.printInfo("\n");
-
-              console.printInfo(PREP_SUMMARY_HEADER);
-              printMethodsSummary();
-              console.printInfo(SEPARATOR);
-              console.printInfo("");
-
-              console.printInfo(TASK_SUMMARY_HEADER);
-              printDagSummary(progressMap, console, dagClient, conf, dag);
-              console.printInfo(SEPARATOR);
-              console.printInfo("");
-
-              if (llapIoEnabled) {
-                console.printInfo(LLAP_IO_SUMMARY_HEADER);
-                printLlapIOSummary(progressMap, console, dagClient);
-                console.printInfo(SEPARATOR);
-              }
-
-              console.printInfo("\n");
-            }
+            success = true;
             running = false;
             done = true;
             break;
@@ -376,6 +351,33 @@ public class TezJobMonitor {
     }
 
     perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.TEZ_RUN_DAG);
+
+    if (isProfileEnabled && success && progressMap != null) {
+
+      double duration = (System.currentTimeMillis() - startTime) / 1000.0;
+      console.printInfo("Status: DAG finished successfully in "
+          + String.format("%.2f seconds", duration));
+      console.printInfo("\n");
+
+      console.printInfo(QUERY_EXEC_SUMMARY_HEADER);
+      printQueryExecutionBreakDown();
+      console.printInfo(SEPARATOR);
+      console.printInfo("");
+
+      console.printInfo(TASK_SUMMARY_HEADER);
+      printDagSummary(progressMap, console, dagClient, conf, dag);
+      console.printInfo(SEPARATOR);
+      console.printInfo("");
+
+      if (llapIoEnabled) {
+        console.printInfo(LLAP_IO_SUMMARY_HEADER);
+        printLlapIOSummary(progressMap, console, dagClient);
+        console.printInfo(SEPARATOR);
+      }
+
+      console.printInfo("\n");
+    }
+
     return rc;
   }
 
@@ -414,37 +416,44 @@ public class TezJobMonitor {
     return (tezCounter == null) ? 0 : tezCounter.getValue();
   }
 
-  private void printMethodsSummary() {
-    long totalInPrepTime = 0;
-
-    String[] perfLoggerReportMethods = {
-        (PerfLogger.PARSE),
-        (PerfLogger.ANALYZE),
-        (PerfLogger.TEZ_BUILD_DAG),
-        (PerfLogger.TEZ_SUBMIT_TO_RUNNING)
-    };
+  private void printQueryExecutionBreakDown() {
 
     /* Build the method summary header */
-    String methodBreakdownHeader = String.format("%-30s %-13s", METHOD, DURATION);
+    String execBreakdownHeader = String.format(OPERATION_SUMMARY, OPERATION, DURATION);
     console.printInfo(SEPARATOR);
-    reprintLineWithColorAsBold(methodBreakdownHeader, Ansi.Color.CYAN);
+    reprintLineWithColorAsBold(execBreakdownHeader, Ansi.Color.CYAN);
     console.printInfo(SEPARATOR);
 
-    for (String method : perfLoggerReportMethods) {
-      long duration = perfLogger.getDuration(method);
-      totalInPrepTime += duration;
-      console.printInfo(String.format("%-30s %11s", method, commaFormat.format(duration)));
-    }
-
-    /*
-     * The counters list above don't capture the total time from TimeToSubmit.startTime till
-     * TezRunDag.startTime, so calculate the duration and print it.
-     */
-    totalInPrepTime = perfLogger.getStartTime(PerfLogger.TEZ_RUN_DAG) -
-        perfLogger.getStartTime(PerfLogger.TIME_TO_SUBMIT);
+    // parse, analyze, optimize and compile
+    long compile = perfLogger.getEndTime(PerfLogger.COMPILE) -
+        perfLogger.getStartTime(PerfLogger.DRIVER_RUN);
+    console.printInfo(String.format(OPERATION_SUMMARY, "Compile Query",
+        secondsFormat.format(compile / 1000.0) + "s"));
+
+    // prepare plan for submission (building DAG, adding resources, creating scratch dirs
etc.)
+    long totalDAGPrep = perfLogger.getStartTime(PerfLogger.TEZ_SUBMIT_DAG) -
+        perfLogger.getEndTime(PerfLogger.COMPILE);
+    console.printInfo(String.format(OPERATION_SUMMARY, "Prepare Plan",
+        secondsFormat.format(totalDAGPrep / 1000.0) + "s"));
+
+    // submit to accept dag (if session is closed, this will include re-opening of session
time,
+    // localizing files for AM, submitting DAG)
+    long submitToAccept = perfLogger.getStartTime(PerfLogger.TEZ_RUN_DAG) -
+        perfLogger.getStartTime(PerfLogger.TEZ_SUBMIT_DAG);
+    console.printInfo(String.format(OPERATION_SUMMARY, "Submit Plan",
+        secondsFormat.format(submitToAccept / 1000.0) + "s"));
+
+    // accept to start dag (schedule wait time, resource wait time etc.)
+    long acceptToStart = perfLogger.getDuration(PerfLogger.TEZ_SUBMIT_TO_RUNNING);
+    console.printInfo(String.format(OPERATION_SUMMARY, "Start",
+        secondsFormat.format(acceptToStart / 1000.0) + "s"));
+
+    // time to actually run the dag (actual dag runtime)
+    long startToEnd = perfLogger.getEndTime(PerfLogger.TEZ_RUN_DAG) -
+        perfLogger.getEndTime(PerfLogger.TEZ_SUBMIT_TO_RUNNING);
+    console.printInfo(String.format(OPERATION_SUMMARY, "Finish",
+        secondsFormat.format(startToEnd / 1000.0) + "s"));
 
-    console.printInfo(String.format("%-30s %11s", TOTAL_PREP_TIME, commaFormat.format(
-        totalInPrepTime)));
   }
 
   private void printDagSummary(Map<String, Progress> progressMap, LogHelper console,
@@ -582,7 +591,7 @@ public class TezJobMonitor {
   }
 
   private void printLlapIOSummary(Map<String, Progress> progressMap, LogHelper console,
-      DAGClient dagClient) throws Exception {
+      DAGClient dagClient) {
     SortedSet<String> keys = new TreeSet<>(progressMap.keySet());
     Set<StatusGetOpts> statusOptions = new HashSet<>(1);
     statusOptions.add(StatusGetOpts.GET_COUNTERS);
@@ -593,8 +602,15 @@ public class TezJobMonitor {
       if (vertexName.startsWith("Reducer")) {
         continue;
       }
-      TezCounters vertexCounters = dagClient.getVertexStatus(vertexName, statusOptions)
-          .getVertexCounters();
+      TezCounters vertexCounters = null;
+      try {
+        vertexCounters = dagClient.getVertexStatus(vertexName, statusOptions)
+            .getVertexCounters();
+      } catch (IOException e) {
+        // best attempt, shouldn't really kill DAG for this
+      } catch (TezException e) {
+        // best attempt, shouldn't really kill DAG for this
+      }
       if (vertexCounters != null) {
         final long selectedRowgroups = getCounterValueByGroupName(vertexCounters,
             counterGroup, LlapIOCounters.SELECTED_ROWGROUPS.name());


Mime
View raw message