Return-Path: X-Original-To: apmail-hive-commits-archive@www.apache.org Delivered-To: apmail-hive-commits-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 0C96E19E20 for ; Tue, 15 Mar 2016 18:17:19 +0000 (UTC) Received: (qmail 42783 invoked by uid 500); 15 Mar 2016 18:17:18 -0000 Delivered-To: apmail-hive-commits-archive@hive.apache.org Received: (qmail 42742 invoked by uid 500); 15 Mar 2016 18:17:18 -0000 Mailing-List: contact commits-help@hive.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: hive-dev@hive.apache.org Delivered-To: mailing list commits@hive.apache.org Received: (qmail 42731 invoked by uid 99); 15 Mar 2016 18:17:18 -0000 Received: from git1-us-west.apache.org (HELO git1-us-west.apache.org) (140.211.11.23) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 15 Mar 2016 18:17:18 +0000 Received: by git1-us-west.apache.org (ASF Mail Server at git1-us-west.apache.org, from userid 33) id A0AFEDFA43; Tue, 15 Mar 2016 18:17:18 +0000 (UTC) Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit From: prasanthj@apache.org To: commits@hive.apache.org Message-Id: <9d6ae269aaaa4b6aa87d1da79bb32113@git.apache.org> X-Mailer: ASF-Git Admin Mailer 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 +0000 (UTC) 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 Authored: Tue Mar 15 13:13:29 2016 -0500 Committer: Prasanth Jayachandran 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 } 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 progressMap = null; while (true) { try { status = dagClient.getDAGStatus(opts, checkInterval); - Map 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 progressMap, LogHelper console, @@ -582,7 +591,7 @@ public class TezJobMonitor { } private void printLlapIOSummary(Map progressMap, LogHelper console, - DAGClient dagClient) throws Exception { + DAGClient dagClient) { SortedSet keys = new TreeSet<>(progressMap.keySet()); Set 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());