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 <[email protected]> Authored: Tue Dec 22 11:03:10 2015 -0500 Committer: ctang <[email protected]> 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); }
