FAQ
Repository: hive
Updated Branches:
   refs/heads/master 4df9b4d20 -> 4f939f5f1


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/4f939f5f
Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/4f939f5f
Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/4f939f5f

Branch: refs/heads/master
Commit: 4f939f5f10236070e677301013dc6b7d4a98aa2c
Parents: 4df9b4d
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:04:57 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 | 44 +++++++++++---------
  .../hadoop/hive/ql/parse/ParseDriver.java | 14 ++++---
  .../service/cli/operation/SQLOperation.java | 8 +---
  9 files changed, 60 insertions(+), 58 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/hive/blob/4f939f5f/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/4f939f5f/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/4f939f5f/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 e9206b9..71ea5d2 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
@@ -2449,11 +2449,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/4f939f5f/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/4f939f5f/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/4f939f5f/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/4f939f5f/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 3d5f3b5..52f5528 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
@@ -368,6 +368,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();

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

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

      try {
@@ -408,12 +426,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);
@@ -466,10 +478,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);

@@ -533,9 +541,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");
      }
    }

@@ -1127,7 +1136,6 @@ 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 = tryAcquireCompileLock(isParallelEnabled,
          command);
@@ -1136,13 +1144,7 @@ public class Driver implements CommandProcessor {
      }

      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();
      }
@@ -1195,6 +1197,7 @@ public class Driver implements CommandProcessor {
        compileLock.lock();
      }

+ LOG.debug("Acquired the compile lock");
      return compileLock;
    }

@@ -1427,7 +1430,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();
@@ -1663,7 +1666,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()) {
@@ -1675,6 +1678,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/4f939f5f/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/4f939f5f/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

  • Ctang at Dec 22, 2015 at 4:25 pm
    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);
            }
  • Ctang at Dec 23, 2015 at 10:18 pm
    Repository: hive
    Updated Branches:
       refs/heads/branch-1 f31061c8c -> 435580f91


    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/435580f9
    Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/435580f9
    Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/435580f9

    Branch: refs/heads/branch-1
    Commit: 435580f9161523c3fc03a2371630690f0dd8e008
    Parents: f31061c
    Author: ctang <ctang.ma@gmail.com>
    Authored: Tue Dec 22 11:03:10 2015 -0500
    Committer: ctang <ctang.ma@gmail.com>
    Committed: Wed Dec 23 17:18:09 2015 -0500

    ----------------------------------------------------------------------
      .../hive/beeline/TestBeeLineWithArgs.java | 2 +-
      .../org/apache/hive/jdbc/TestJdbcDriver2.java | 7 +++---
      .../TestOperationLoggingAPIWithMr.java | 7 +++---
      .../TestOperationLoggingAPIWithTez.java | 7 +++---
      .../java/org/apache/hadoop/hive/ql/Driver.java | 26 ++++++++++++++------
      .../apache/hadoop/hive/ql/log/PerfLogger.java | 5 +---
      .../hadoop/hive/ql/parse/ParseDriver.java | 14 +++++++----
      .../service/cli/operation/SQLOperation.java | 3 +--
      8 files changed, 42 insertions(+), 29 deletions(-)
    ----------------------------------------------------------------------


    http://git-wip-us.apache.org/repos/asf/hive/blob/435580f9/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 19ee621..beb0c47 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/435580f9/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 146ba2a..54c7ff3 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
    @@ -2285,11 +2285,11 @@ 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"
          };
          String sql = "select count(*) from " + tableName;

    @@ -2371,6 +2371,7 @@ public void testParseUrlHttpMode() throws SQLException, JdbcUriParseException,

          String accumulatedLogs = stringBuilder.toString();
          for (String expectedLog : expectedLogs) {
    + System.out.println(expectedLog);
            assertTrue(accumulatedLogs.contains(expectedLog));
          }
        }

    http://git-wip-us.apache.org/repos/asf/hive/blob/435580f9/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 920b563..d68ab58 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,11 +42,12 @@ public class TestOperationLoggingAPIWithMr extends OperationLoggingAPITestBase{
        public static void setUpBeforeClass() throws Exception {
          tableName = "testOperationLoggingAPIWithMr_table";
          expectedLogsVerbose = new String[]{
    - "Parsing command",
    - "Parse Completed",
    + "Compiling command",
    + "Completed compiling command",
            "Starting Semantic Analysis",
            "Semantic Analysis Completed",
    - "Starting command"
    + "Executing command",
    + "Completed executing command"
          };
          expectedLogsExecution = new String[]{
            "Number of reduce tasks determined at compile time",

    http://git-wip-us.apache.org/repos/asf/hive/blob/435580f9/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 31f34b2..dadb785 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
    @@ -18,11 +18,12 @@ public class TestOperationLoggingAPIWithTez extends OperationLoggingAPITestBase
        public static void setUpBeforeClass() throws Exception {
          tableName = "testOperationLoggingAPIWithTez_table";
          expectedLogsVerbose = new String[]{
    - "Parsing command",
    - "Parse Completed",
    + "Compiling command",
    + "Completed compiling command",
            "Starting Semantic Analysis",
            "Semantic Analysis Completed",
    - "Starting command"
    + "Executing command",
    + "Completed executing command"
          };
          expectedLogsExecution = new String[]{
            "Executing on YARN cluster with App id",

    http://git-wip-us.apache.org/repos/asf/hive/blob/435580f9/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 4b032cc..06aa3c9 100644
    --- a/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
    +++ b/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
    @@ -369,6 +369,16 @@ public class Driver implements CommandProcessor {
          PerfLogger perfLogger = PerfLogger.getPerfLogger();
          perfLogger.PerfLogBegin(CLASS_NAME, PerfLogger.COMPILE);

    + command = new VariableSubstitution().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();

    @@ -386,6 +396,8 @@ public class Driver implements CommandProcessor {
          String queryId = QueryPlan.makeQueryId();
          conf.setVar(HiveConf.ConfVars.HIVEQUERYID, queryId);

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

          try {
    @@ -405,7 +417,6 @@ public class Driver implements CommandProcessor {
            };
            ShutdownHookManager.addShutdownHook(shutdownRunner, SHUTDOWN_HOOK_PRIORITY);

    - command = new VariableSubstitution().substitute(conf, command);
            ctx = new Context(conf);
            ctx.setTryCount(getTryCount());
            ctx.setCmd(command);
    @@ -452,10 +463,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);

    @@ -519,9 +526,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");
          }
        }

    @@ -1163,6 +1171,7 @@ public class Driver implements CommandProcessor {

        private int compileInternal(String command) {
          int ret;
    + LOG.debug("Acquire a monitor for compiling query");
          synchronized (compileMonitor) {
            ret = compile(command);
          }
    @@ -1431,7 +1440,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();
    @@ -1666,7 +1675,7 @@ public class Driver implements CommandProcessor {
              conf.setVar(HiveConf.ConfVars.HADOOPJOBNAME, "");
            }
            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()) {
    @@ -1678,6 +1687,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/435580f9/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
    ----------------------------------------------------------------------
    diff --git a/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java b/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
    index f202991..e020904 100644
    --- a/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
    +++ b/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
    @@ -131,9 +131,8 @@ public class PerfLogger {
        public long PerfLogEnd(String callerName, String method) {
          Long startTime = startTimes.get(method);
          long endTime = System.currentTimeMillis();
    - long duration = -1;
    -
          endTimes.put(method, new Long(endTime));
    + long duration = startTime == null ? -1 : endTime - startTime.longValue();

          StringBuilder sb = new StringBuilder("</PERFLOG method=").append(method);
          if (startTime != null) {
    @@ -141,7 +140,6 @@ public class PerfLogger {
          }
          sb.append(" end=").append(endTime);
          if (startTime != null) {
    - duration = endTime - startTime.longValue();
            sb.append(" duration=").append(duration);
          }
          sb.append(" from=").append(callerName).append(">");
    @@ -156,7 +154,6 @@ public class PerfLogger {
         * @param _log
         */
        public void close(Log _log, QueryPlan queryPlan) {
    -
        }

        public Long getStartTime(String method) {

    http://git-wip-us.apache.org/repos/asf/hive/blob/435580f9/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 debd5ac..04032a5 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/435580f9/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 5c2f13d..6c8a066 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
    @@ -105,8 +105,7 @@ public class SQLOperation extends ExecuteStatementOperation {
            // For now, we disable the test attempts.
            driver.setTryCount(Integer.MAX_VALUE);

    - String subStatement = new VariableSubstitution().substitute(sqlOperationConf, statement);
    - response = driver.compileAndRespond(subStatement);
    + response = driver.compileAndRespond(statement);
            if (0 != response.getResponseCode()) {
              throw toSQLException("Error while compiling statement", response);
            }

Related Discussions

Discussion Navigation
viewthread | post
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