FAQ
Repository: hive
Updated Branches:
   refs/heads/branch-2.0 ec2184569 -> 08e1064f9


HIVE-12713: Miscellaneous improvements in driver compile and execute logging (Chaoyu Tang, reviewed by Xuefu Zhang)


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

Branch: refs/heads/branch-2.0
Commit: 08e1064f9a2e6c91e8369ab90acb2262f677da00
Parents: ec21845
Author: ctang <ctang.ma@gmail.com>
Authored: Tue Dec 22 11:03:10 2015 -0500
Committer: ctang <ctang.ma@gmail.com>
Committed: Tue Dec 22 11:24:52 2015 -0500

----------------------------------------------------------------------
  .../apache/hadoop/hive/ql/log/PerfLogger.java | 20 ++++-----
  .../hive/beeline/TestBeeLineWithArgs.java | 2 +-
  .../org/apache/hive/jdbc/TestJdbcDriver2.java | 7 ++--
  .../hive/jdbc/cbo_rp_TestJdbcDriver2.java | 7 ++--
  .../TestOperationLoggingAPIWithMr.java | 9 ++--
  .../TestOperationLoggingAPIWithTez.java | 7 ++--
  .../java/org/apache/hadoop/hive/ql/Driver.java | 43 +++++++++++---------
  .../hadoop/hive/ql/parse/ParseDriver.java | 14 ++++---
  .../service/cli/operation/SQLOperation.java | 8 +---
  9 files changed, 59 insertions(+), 58 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
----------------------------------------------------------------------
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
index 98ebd50..d4194cf 100644
--- a/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
+++ b/common/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
@@ -117,10 +117,10 @@ public class PerfLogger {
     * @param method method or ID that identifies this perf log element.
     */
    public void PerfLogBegin(String callerName, String method) {
+ long startTime = System.currentTimeMillis();
+ startTimes.put(method, new Long(startTime));
      if (LOG.isDebugEnabled()) {
- long startTime = System.currentTimeMillis();
        LOG.debug("<PERFLOG method=" + method + " from=" + callerName + ">");
- startTimes.put(method, new Long(startTime));
        beginMetrics(method);
      }
    }
@@ -141,20 +141,18 @@ public class PerfLogger {
     * @return long duration the difference between now and startTime, or -1 if startTime is null
     */
    public long PerfLogEnd(String callerName, String method, String additionalInfo) {
- if (LOG.isDebugEnabled()) {
- Long startTime = startTimes.get(method);
- long endTime = System.currentTimeMillis();
- long duration = -1;
-
- endTimes.put(method, new Long(endTime));
+ Long startTime = startTimes.get(method);
+ long endTime = System.currentTimeMillis();
+ endTimes.put(method, new Long(endTime));
+ long duration = startTime == null ? -1 : endTime - startTime.longValue();

+ if (LOG.isDebugEnabled()) {
        StringBuilder sb = new StringBuilder("</PERFLOG method=").append(method);
        if (startTime != null) {
          sb.append(" start=").append(startTime);
        }
        sb.append(" end=").append(endTime);
        if (startTime != null) {
- duration = endTime - startTime.longValue();
          sb.append(" duration=").append(duration);
        }
        sb.append(" from=").append(callerName);
@@ -165,10 +163,8 @@ public class PerfLogger {
        LOG.debug(sb.toString());

        endMetrics(method);
-
- return duration;
      }
- return -1;
+ return duration;
    }

    public Long getStartTime(String method) {

http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/itests/hive-unit/src/test/java/org/apache/hive/beeline/TestBeeLineWithArgs.java
----------------------------------------------------------------------
diff --git a/itests/hive-unit/src/test/java/org/apache/hive/beeline/TestBeeLineWithArgs.java b/itests/hive-unit/src/test/java/org/apache/hive/beeline/TestBeeLineWithArgs.java
index 7cc0acf..d5f692b 100644
--- a/itests/hive-unit/src/test/java/org/apache/hive/beeline/TestBeeLineWithArgs.java
+++ b/itests/hive-unit/src/test/java/org/apache/hive/beeline/TestBeeLineWithArgs.java
@@ -674,7 +674,7 @@ public class TestBeeLineWithArgs {
      final String SCRIPT_TEXT = "set hive.support.concurrency = false;\n" +
          "!set silent true\n" +
          "select count(*) from " + tableName + ";\n";
- final String EXPECTED_PATTERN = "Parsing command";
+ final String EXPECTED_PATTERN = "Executing command";
      testScriptFile(SCRIPT_TEXT, EXPECTED_PATTERN, false, getBaseArgs(miniHS2.getBaseJdbcURL()));
    }


http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/itests/hive-unit/src/test/java/org/apache/hive/jdbc/TestJdbcDriver2.java
----------------------------------------------------------------------
diff --git a/itests/hive-unit/src/test/java/org/apache/hive/jdbc/TestJdbcDriver2.java b/itests/hive-unit/src/test/java/org/apache/hive/jdbc/TestJdbcDriver2.java
index 8cb9689..86a8a8e 100644
--- a/itests/hive-unit/src/test/java/org/apache/hive/jdbc/TestJdbcDriver2.java
+++ b/itests/hive-unit/src/test/java/org/apache/hive/jdbc/TestJdbcDriver2.java
@@ -2441,11 +2441,12 @@ public void testParseUrlHttpMode() throws SQLException, JdbcUriParseException,
    public void testGetQueryLog() throws Exception {
      // Prepare
      String[] expectedLogs = {
- "Parsing command",
- "Parse Completed",
+ "Compiling command",
+ "Completed compiling command",
          "Starting Semantic Analysis",
          "Semantic Analysis Completed",
- "Starting command"
+ "Executing command",
+ "Completed executing command"
      };
      String sql = "select count(*) from " + tableName;


http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/itests/hive-unit/src/test/java/org/apache/hive/jdbc/cbo_rp_TestJdbcDriver2.java
----------------------------------------------------------------------
diff --git a/itests/hive-unit/src/test/java/org/apache/hive/jdbc/cbo_rp_TestJdbcDriver2.java b/itests/hive-unit/src/test/java/org/apache/hive/jdbc/cbo_rp_TestJdbcDriver2.java
index c66f166..68a2c67 100644
--- a/itests/hive-unit/src/test/java/org/apache/hive/jdbc/cbo_rp_TestJdbcDriver2.java
+++ b/itests/hive-unit/src/test/java/org/apache/hive/jdbc/cbo_rp_TestJdbcDriver2.java
@@ -2296,11 +2296,12 @@ public void testParseUrlHttpMode() throws SQLException, JdbcUriParseException,
    public void testGetQueryLog() throws Exception {
      // Prepare
      String[] expectedLogs = {
- "Parsing command",
- "Parse Completed",
+ "Compiling command",
+ "Completed compiling command",
          "Starting Semantic Analysis",
          "Semantic Analysis Completed",
- "Starting command"
+ "Executing command",
+ "Completed executing command"
      };
      String sql = "select count(*) from " + tableName;


http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java
----------------------------------------------------------------------
diff --git a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java
index d21571e..b8462c6 100644
--- a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java
+++ b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithMr.java
@@ -42,13 +42,14 @@ public class TestOperationLoggingAPIWithMr extends OperationLoggingAPITestBase {
    public static void setUpBeforeClass() throws Exception {
      tableName = "testOperationLoggingAPIWithMr_table";
      expectedLogsVerbose = new String[]{
- "Parsing command",
- "Parse Completed",
- "Starting Semantic Analysis",
+ "Starting Semantic Analysis"
      };
      expectedLogsExecution = new String[]{
+ "Compiling command",
+ "Completed compiling command",
        "Total jobs",
- "Starting command",
+ "Executing command",
+ "Completed executing command",
        "Semantic Analysis Completed",
        "Number of reduce tasks determined at compile time",
        "number of splits",

http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java
----------------------------------------------------------------------
diff --git a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java
index 8b21647..bee1447 100644
--- a/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java
+++ b/itests/hive-unit/src/test/java/org/apache/hive/service/cli/operation/TestOperationLoggingAPIWithTez.java
@@ -35,12 +35,13 @@ public class TestOperationLoggingAPIWithTez extends OperationLoggingAPITestBase
    public static void setUpBeforeClass() throws Exception {
      tableName = "testOperationLoggingAPIWithTez_table";
      expectedLogsVerbose = new String[]{
- "Parsing command",
- "Parse Completed",
        "Starting Semantic Analysis"
      };
      expectedLogsExecution = new String[]{
- "Starting command",
+ "Compiling command",
+ "Completed compiling command",
+ "Executing command",
+ "Completed executing command",
        "Semantic Analysis Completed",
        "Executing on YARN cluster with App id",
        "Setting Tez DAG access"

http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
----------------------------------------------------------------------
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
index d81e17a..2deeb48 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
@@ -375,6 +375,22 @@ public class Driver implements CommandProcessor {
      PerfLogger perfLogger = SessionState.getPerfLogger();
      perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.COMPILE);

+ command = new VariableSubstitution(new HiveVariableSource() {
+ @Override
+ public Map<String, String> getHiveVariable() {
+ return SessionState.get().getHiveVariables();
+ }
+ }).substitute(conf, command);
+
+ String queryStr = command;
+
+ try {
+ // command should be redacted to avoid to logging sensitive data
+ queryStr = HookUtils.redactLogString(conf, command);
+ } catch (Exception e) {
+ LOG.warn("WARNING! Query command could not be redacted." + e);
+ }
+
      //holder for parent command type/string when executing reentrant queries
      QueryState queryState = new QueryState();

@@ -395,6 +411,8 @@ public class Driver implements CommandProcessor {
        conf.setVar(HiveConf.ConfVars.HIVEQUERYID, queryId);
      }

+ LOG.info("Compiling command(queryId=" + queryId + "): " + queryStr);
+
      SessionState.get().setupQueryCurrentTimestamp();

      try {
@@ -415,12 +433,6 @@ public class Driver implements CommandProcessor {
        };
        ShutdownHookManager.addShutdownHook(shutdownRunner, SHUTDOWN_HOOK_PRIORITY);

- command = new VariableSubstitution(new HiveVariableSource() {
- @Override
- public Map<String, String> getHiveVariable() {
- return SessionState.get().getHiveVariables();
- }
- }).substitute(conf, command);
        ctx = new Context(conf);
        ctx.setTryCount(getTryCount());
        ctx.setCmd(command);
@@ -473,10 +485,6 @@ public class Driver implements CommandProcessor {
        sem.validate();
        perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.ANALYZE);

- // Command should be redacted before passing it to the QueryPlan in order
- // to avoid returning sensitive data
- String queryStr = HookUtils.redactLogString(conf, command);
-
        // get the output schema
        schema = getSchema(sem, conf);

@@ -540,9 +548,10 @@ public class Driver implements CommandProcessor {
        return error.getErrorCode();//todo: this is bad if returned as cmd shell exit
        // since it exceeds valid range of shell return values
      } finally {
- perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.COMPILE);
+ double duration = perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.COMPILE)/1000.00;
        dumpMetaCallTimingWithoutEx("compilation");
        restoreSession(queryState);
+ LOG.info("Completed compiling command(queryId=" + queryId + "); Time taken: " + duration + " seconds");
      }
    }

@@ -1217,19 +1226,12 @@ public class Driver implements CommandProcessor {

    private static final ReentrantLock globalCompileLock = new ReentrantLock();
    private int compileInternal(String command) {
- boolean isParallelEnabled = SessionState.get().isHiveServerQuery() && this.isParallelEnabled;
      int ret;
      final ReentrantLock compileLock = isParallelEnabled
          ? SessionState.get().getCompileLock() : globalCompileLock;
      compileLock.lock();
      try {
- if (isParallelEnabled && LOG.isDebugEnabled()) {
- LOG.debug("Entering compile: " + command);
- }
        ret = compile(command);
- if (isParallelEnabled && LOG.isDebugEnabled()) {
- LOG.debug("Done with compile: " + command);
- }
      } finally {
        compileLock.unlock();
      }
@@ -1473,7 +1475,7 @@ public class Driver implements CommandProcessor {
      maxthreads = HiveConf.getIntVar(conf, HiveConf.ConfVars.EXECPARALLETHREADNUMBER);

      try {
- LOG.info("Starting command(queryId=" + queryId + "): " + queryStr);
+ LOG.info("Executing command(queryId=" + queryId + "): " + queryStr);
        // compile and execute can get called from different threads in case of HS2
        // so clear timing in this thread's Hive object before proceeding.
        Hive.get().clearMetaCallTiming();
@@ -1709,7 +1711,7 @@ public class Driver implements CommandProcessor {
          conf.set(MRJobConfig.JOB_NAME, "");
        }
        dumpMetaCallTimingWithoutEx("execution");
- perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.DRIVER_EXECUTE);
+ double duration = perfLogger.PerfLogEnd(CLASS_NAME, PerfLogger.DRIVER_EXECUTE)/1000.00;

        Map<String, MapRedStats> stats = SessionState.get().getMapRedStats();
        if (stats != null && !stats.isEmpty()) {
@@ -1721,6 +1723,7 @@ public class Driver implements CommandProcessor {
          }
          console.printInfo("Total MapReduce CPU Time Spent: " + Utilities.formatMsecToStr(totalCpu));
        }
+ LOG.info("Completed executing command(queryId=" + queryId + "); Time taken: " + duration + " seconds");
      }
      plan.setDone();


http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/ql/src/java/org/apache/hadoop/hive/ql/parse/ParseDriver.java
----------------------------------------------------------------------
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/parse/ParseDriver.java b/ql/src/java/org/apache/hadoop/hive/ql/parse/ParseDriver.java
index c33bb66..90a9a4e 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/parse/ParseDriver.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/parse/ParseDriver.java
@@ -180,9 +180,11 @@ public class ParseDriver {
     *
     * @return parsed AST
     */
- public ASTNode parse(String command, Context ctx, boolean setTokenRewriteStream)
+ public ASTNode parse(String command, Context ctx, boolean setTokenRewriteStream)
        throws ParseException {
- LOG.info("Parsing command: " + command);
+ if (LOG.isDebugEnabled()) {
+ LOG.debug("Parsing command: " + command);
+ }

      HiveLexerX lexer = new HiveLexerX(new ANTLRNoCaseStringStream(command));
      TokenRewriteStream tokens = new TokenRewriteStream(lexer);
@@ -206,7 +208,7 @@ public class ParseDriver {
      }

      if (lexer.getErrors().size() == 0 && parser.errors.size() == 0) {
- LOG.info("Parse Completed");
+ LOG.debug("Parse Completed");
      } else if (lexer.getErrors().size() != 0) {
        throw new ParseException(lexer.getErrors());
      } else {
@@ -230,7 +232,9 @@ public class ParseDriver {
     * translation process.
     */
    public ASTNode parseSelect(String command, Context ctx) throws ParseException {
- LOG.info("Parsing command: " + command);
+ if (LOG.isDebugEnabled()) {
+ LOG.debug("Parsing command: " + command);
+ }

      HiveLexerX lexer = new HiveLexerX(new ANTLRNoCaseStringStream(command));
      TokenRewriteStream tokens = new TokenRewriteStream(lexer);
@@ -248,7 +252,7 @@ public class ParseDriver {
      }

      if (lexer.getErrors().size() == 0 && parser.errors.size() == 0) {
- LOG.info("Parse Completed");
+ LOG.debug("Parse Completed");
      } else if (lexer.getErrors().size() != 0) {
        throw new ParseException(lexer.getErrors());
      } else {

http://git-wip-us.apache.org/repos/asf/hive/blob/08e1064f/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java
----------------------------------------------------------------------
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
index d90dd0d..2eaab4a 100644
--- a/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java
+++ b/service/src/java/org/apache/hive/service/cli/operation/SQLOperation.java
@@ -124,13 +124,7 @@ public class SQLOperation extends ExecuteStatementOperation {
        // For now, we disable the test attempts.
        driver.setTryCount(Integer.MAX_VALUE);

- String subStatement = new VariableSubstitution(new HiveVariableSource() {
- @Override
- public Map<String, String> getHiveVariable() {
- return SessionState.get().getHiveVariables();
- }
- }).substitute(sqlOperationConf, statement);
- response = driver.compileAndRespond(subStatement);
+ response = driver.compileAndRespond(statement);
        if (0 != response.getResponseCode()) {
          throw toSQLException("Error while compiling statement", response);
        }

Search Discussions

Discussion Posts

Previous

Follow ups

Related Discussions

Discussion Navigation
viewthread | post
posts ‹ prev | 2 of 3 | next ›
Discussion Overview
groupcommits @
categorieshive, hadoop
postedDec 22, '15 at 4:13p
activeDec 23, '15 at 10:18p
posts3
users1
websitehive.apache.org

1 user in discussion

Ctang: 3 posts

People

Translate

site design / logo © 2021 Grokbase