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...@gmail.com> Authored: Tue Dec 22 11:03:10 2015 -0500 Committer: ctang <ctang...@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); }
