You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hive.apache.org by vi...@apache.org on 2015/10/30 22:59:12 UTC
[2/2] hive git commit: HIVE-12249: Improve logging with tez (Vikram
Dixit K, reviewed by Sergey Shelukhin)
HIVE-12249: Improve logging with tez (Vikram Dixit K, reviewed by Sergey Shelukhin)
Project: http://git-wip-us.apache.org/repos/asf/hive/repo
Commit: http://git-wip-us.apache.org/repos/asf/hive/commit/d4df2aee
Tree: http://git-wip-us.apache.org/repos/asf/hive/tree/d4df2aee
Diff: http://git-wip-us.apache.org/repos/asf/hive/diff/d4df2aee
Branch: refs/heads/master
Commit: d4df2aee19e262898676d9cdfae5c8c07097d19b
Parents: f958de0
Author: vikram <vi...@hortonworks.com>
Authored: Fri Oct 30 14:55:05 2015 -0700
Committer: vikram <vi...@hortonworks.com>
Committed: Fri Oct 30 14:55:05 2015 -0700
----------------------------------------------------------------------
.../org/apache/hadoop/hive/cli/CliDriver.java | 7 +++++++
.../org/apache/hadoop/hive/conf/HiveConf.java | 20 ++++++++++++++++++-
.../apache/hadoop/hive/ql/exec/tez/TezTask.java | 9 +++++++++
.../apache/hadoop/hive/ql/hooks/ATSHook.java | 21 ++++++++++++++------
ql/src/test/queries/clientpositive/mrr.q | 2 ++
.../service/cli/session/HiveSessionImpl.java | 21 ++++++++++++++++++++
6 files changed, 73 insertions(+), 7 deletions(-)
----------------------------------------------------------------------
http://git-wip-us.apache.org/repos/asf/hive/blob/d4df2aee/cli/src/java/org/apache/hadoop/hive/cli/CliDriver.java
----------------------------------------------------------------------
diff --git a/cli/src/java/org/apache/hadoop/hive/cli/CliDriver.java b/cli/src/java/org/apache/hadoop/hive/cli/CliDriver.java
index 30ec14b..82d064d 100644
--- a/cli/src/java/org/apache/hadoop/hive/cli/CliDriver.java
+++ b/cli/src/java/org/apache/hadoop/hive/cli/CliDriver.java
@@ -101,6 +101,7 @@ public class CliDriver {
private final LogHelper console;
protected ConsoleReader reader;
private Configuration conf;
+ private final String originalThreadName;
public CliDriver() {
SessionState ss = SessionState.get();
@@ -108,11 +109,15 @@ public class CliDriver {
Logger LOG = LoggerFactory.getLogger("CliDriver");
LOG.debug("CliDriver inited with classpath {}", System.getProperty("java.class.path"));
console = new LogHelper(LOG);
+ originalThreadName = Thread.currentThread().getName();
}
public int processCmd(String cmd) {
CliSessionState ss = (CliSessionState) SessionState.get();
ss.setLastCommand(cmd);
+
+ String callerInfo = ss.getConf().getLogIdVar(ss.getSessionId());
+ Thread.currentThread().setName(callerInfo + " " + originalThreadName);
// Flush the print stream, so it doesn't include output from the last command
ss.err.flush();
String cmd_trimmed = cmd.trim();
@@ -182,6 +187,7 @@ public class CliDriver {
}
}
+ Thread.currentThread().setName(originalThreadName);
return ret;
}
@@ -698,6 +704,7 @@ public class CliDriver {
SessionState.start(ss);
}
+ Thread.currentThread().setName(conf.getLogIdVar(ss.getSessionId()) + " " + originalThreadName);
// execute cli driver work
try {
return executeDriver(ss, conf, oproc);
http://git-wip-us.apache.org/repos/asf/hive/blob/d4df2aee/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java
----------------------------------------------------------------------
diff --git a/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java b/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java
index 936ef54..a55e962 100644
--- a/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java
+++ b/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java
@@ -83,6 +83,7 @@ public class HiveConf extends Configuration {
private Pattern modWhiteListPattern = null;
private volatile boolean isSparkConfigUpdated = false;
+ private static final int LOG_PREFIX_LENGTH = 64;
public boolean getSparkConfigUpdated() {
return isSparkConfigUpdated;
@@ -2392,7 +2393,10 @@ public class HiveConf extends Configuration {
HIVE_TEZ_ENABLE_MEMORY_MANAGER("hive.tez.enable.memory.manager", true,
"Enable memory manager for tez"),
HIVE_HASH_TABLE_INFLATION_FACTOR("hive.hash.table.inflation.factor", (float) 2.0,
- "Expected inflation factor between disk/in memory representation of hash tables");
+ "Expected inflation factor between disk/in memory representation of hash tables"),
+ HIVE_LOG_TRACE_ID("hive.log.trace.id", "",
+ "Log tracing id that can be used by upstream clients for tracking respective logs. " +
+ "Truncated to " + LOG_PREFIX_LENGTH + " characters. Defaults to use auto-generated session id.");
public final String varname;
@@ -2838,6 +2842,20 @@ public class HiveConf extends Configuration {
return conf.get(var.varname, defaultVal);
}
+ public String getLogIdVar(String defaultValue) {
+ String retval = getVar(ConfVars.HIVE_LOG_TRACE_ID);
+ if (retval.equals("")) {
+ l4j.info("Using the default value passed in for log id: " + defaultValue);
+ retval = defaultValue;
+ }
+ if (retval.length() > LOG_PREFIX_LENGTH) {
+ l4j.warn("The original log id prefix is " + retval + " has been truncated to "
+ + retval.substring(0, LOG_PREFIX_LENGTH - 1));
+ retval = retval.substring(0, LOG_PREFIX_LENGTH - 1);
+ }
+ return retval;
+ }
+
public static void setVar(Configuration conf, ConfVars var, String val) {
assert (var.valClass == String.class) : var.varname;
conf.set(var.varname, val);
http://git-wip-us.apache.org/repos/asf/hive/blob/d4df2aee/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezTask.java
----------------------------------------------------------------------
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezTask.java b/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezTask.java
index 032a9e6..a6d911d 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezTask.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/exec/tez/TezTask.java
@@ -54,6 +54,7 @@ import org.apache.hadoop.mapred.JobConf;
import org.apache.hadoop.util.StringUtils;
import org.apache.hadoop.yarn.api.records.LocalResource;
import org.apache.hadoop.yarn.api.records.LocalResourceType;
+import org.apache.tez.client.CallerContext;
import org.apache.tez.client.TezClient;
import org.apache.tez.common.counters.CounterGroup;
import org.apache.tez.common.counters.TezCounter;
@@ -163,6 +164,14 @@ public class TezTask extends Task<TezWork> {
// next we translate the TezWork to a Tez DAG
DAG dag = build(jobConf, work, scratchDir, appJarLr, additionalLr, ctx);
+ if (driverContext.getCtx() == null) {
+ boolean a = false;
+ }
+ CallerContext callerContext = CallerContext.create("HIVE",
+ conf.getLogIdVar(SessionState.get().getSessionId()) + " "
+ + conf.getVar(HiveConf.ConfVars.HIVEQUERYID),
+ "HIVE_QUERY_ID", queryPlan.getQueryStr());
+ dag.setCallerContext(callerContext);
// Add the extra resources to the dag
addExtraResourcesToDag(session, dag, inputOutputJars, inputOutputLocalResources);
http://git-wip-us.apache.org/repos/asf/hive/blob/d4df2aee/ql/src/java/org/apache/hadoop/hive/ql/hooks/ATSHook.java
----------------------------------------------------------------------
diff --git a/ql/src/java/org/apache/hadoop/hive/ql/hooks/ATSHook.java b/ql/src/java/org/apache/hadoop/hive/ql/hooks/ATSHook.java
index 5610fab..38b6b5d 100644
--- a/ql/src/java/org/apache/hadoop/hive/ql/hooks/ATSHook.java
+++ b/ql/src/java/org/apache/hadoop/hive/ql/hooks/ATSHook.java
@@ -26,11 +26,13 @@ import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.apache.hadoop.conf.Configuration;
import org.apache.hadoop.hive.conf.HiveConf;
+import org.apache.hadoop.hive.conf.HiveConf.ConfVars;
import org.apache.hadoop.hive.ql.QueryPlan;
import org.apache.hadoop.hive.ql.exec.ExplainTask;
import org.apache.hadoop.hive.ql.exec.TaskFactory;
import org.apache.hadoop.hive.ql.exec.Utilities;
import org.apache.hadoop.hive.ql.plan.ExplainWork;
+import org.apache.hadoop.hive.ql.session.SessionState;
import org.apache.hadoop.util.StringUtils;
import org.apache.hadoop.yarn.api.records.timeline.TimelineEntity;
import org.apache.hadoop.yarn.api.records.timeline.TimelineEvent;
@@ -52,7 +54,10 @@ public class ATSHook implements ExecuteWithHookContext {
private static TimelineClient timelineClient;
private enum EntityTypes { HIVE_QUERY_ID };
private enum EventTypes { QUERY_SUBMITTED, QUERY_COMPLETED };
- private enum OtherInfoTypes { QUERY, STATUS, TEZ, MAPRED };
+
+ private enum OtherInfoTypes {
+ QUERY, STATUS, TEZ, MAPRED, INVOKER_INFO, THREAD_NAME
+ };
private enum PrimaryFilterTypes { user, requestuser, operationid };
private static final int WAIT_TIME = 3;
@@ -104,7 +109,7 @@ public class ATSHook implements ExecuteWithHookContext {
String user = hookContext.getUgi().getUserName();
String requestuser = hookContext.getUserName();
if (hookContext.getUserName() == null ){
- requestuser = hookContext.getUgi().getUserName() ;
+ requestuser = hookContext.getUgi().getUserName() ;
}
int numMrJobs = Utilities.getMRTasks(plan.getRootTasks()).size();
int numTezJobs = Utilities.getTezTasks(plan.getRootTasks()).size();
@@ -133,8 +138,9 @@ public class ATSHook implements ExecuteWithHookContext {
explain.initialize(conf, plan, null);
String query = plan.getQueryStr();
JSONObject explainPlan = explain.getJSONPlan(null, work);
- fireAndForget(conf, createPreHookEvent(queryId, query,
- explainPlan, queryStartTime, user, requestuser, numMrJobs, numTezJobs, opId));
+ String logID = conf.getLogIdVar(SessionState.get().getSessionId());
+ fireAndForget(conf, createPreHookEvent(queryId, query, explainPlan, queryStartTime,
+ user, requestuser, numMrJobs, numTezJobs, opId, logID));
break;
case POST_EXEC_HOOK:
fireAndForget(conf, createPostHookEvent(queryId, currentTime, user, requestuser, true, opId));
@@ -154,7 +160,8 @@ public class ATSHook implements ExecuteWithHookContext {
}
TimelineEntity createPreHookEvent(String queryId, String query, JSONObject explainPlan,
- long startTime, String user, String requestuser, int numMrJobs, int numTezJobs, String opId) throws Exception {
+ long startTime, String user, String requestuser, int numMrJobs, int numTezJobs, String opId,
+ String logID) throws Exception {
JSONObject queryObj = new JSONObject(new LinkedHashMap<>());
queryObj.put("queryText", query);
@@ -171,7 +178,7 @@ public class ATSHook implements ExecuteWithHookContext {
atsEntity.setEntityType(EntityTypes.HIVE_QUERY_ID.name());
atsEntity.addPrimaryFilter(PrimaryFilterTypes.user.name(), user);
atsEntity.addPrimaryFilter(PrimaryFilterTypes.requestuser.name(), requestuser);
-
+
if (opId != null) {
atsEntity.addPrimaryFilter(PrimaryFilterTypes.operationid.name(), opId);
}
@@ -184,6 +191,8 @@ public class ATSHook implements ExecuteWithHookContext {
atsEntity.addOtherInfo(OtherInfoTypes.QUERY.name(), queryObj.toString());
atsEntity.addOtherInfo(OtherInfoTypes.TEZ.name(), numTezJobs > 0);
atsEntity.addOtherInfo(OtherInfoTypes.MAPRED.name(), numMrJobs > 0);
+ atsEntity.addOtherInfo(OtherInfoTypes.INVOKER_INFO.name(), logID);
+ atsEntity.addOtherInfo(OtherInfoTypes.THREAD_NAME.name(), Thread.currentThread().getName());
return atsEntity;
}
http://git-wip-us.apache.org/repos/asf/hive/blob/d4df2aee/ql/src/test/queries/clientpositive/mrr.q
----------------------------------------------------------------------
diff --git a/ql/src/test/queries/clientpositive/mrr.q b/ql/src/test/queries/clientpositive/mrr.q
index 2ced4db..a8eddaf 100644
--- a/ql/src/test/queries/clientpositive/mrr.q
+++ b/ql/src/test/queries/clientpositive/mrr.q
@@ -1,5 +1,6 @@
set hive.explain.user=false;
set hive.auto.convert.join.noconditionaltask.size=60000000;
+set hive.log.trace.id=mrrTest;
-- simple query with multiple reduce stages
-- SORT_QUERY_RESULTS
@@ -50,6 +51,7 @@ WHERE
s1.cnt > 1
ORDER BY s1.key;
+set hive.log.trace.id=Test2;
set hive.auto.convert.join=true;
-- query with broadcast join in the reduce stage
EXPLAIN
http://git-wip-us.apache.org/repos/asf/hive/blob/d4df2aee/service/src/java/org/apache/hive/service/cli/session/HiveSessionImpl.java
----------------------------------------------------------------------
diff --git a/service/src/java/org/apache/hive/service/cli/session/HiveSessionImpl.java b/service/src/java/org/apache/hive/service/cli/session/HiveSessionImpl.java
index 50e938e..27d11df 100644
--- a/service/src/java/org/apache/hive/service/cli/session/HiveSessionImpl.java
+++ b/service/src/java/org/apache/hive/service/cli/session/HiveSessionImpl.java
@@ -310,6 +310,11 @@ public class HiveSessionImpl implements HiveSession {
if (userAccess) {
lastAccessTime = System.currentTimeMillis();
}
+ // set the thread name with the logging prefix.
+ String logPrefix = getHiveConf().getLogIdVar(sessionState.getSessionId());
+ LOG.info(
+ "Prefixing the thread name (" + Thread.currentThread().getName() + ") with " + logPrefix);
+ Thread.currentThread().setName(logPrefix + Thread.currentThread().getName());
Hive.set(sessionHive);
}
@@ -321,6 +326,22 @@ public class HiveSessionImpl implements HiveSession {
* @see org.apache.hive.service.server.ThreadWithGarbageCleanup#finalize()
*/
protected synchronized void release(boolean userAccess) {
+ if (sessionState != null) {
+ // can be null in-case of junit tests. skip reset.
+ // reset thread name at release time.
+ String[] names = Thread.currentThread().getName()
+ .split(getHiveConf().getLogIdVar(sessionState.getSessionId()));
+ String threadName = null;
+ if (names.length > 1) {
+ threadName = names[names.length - 1];
+ } else if (names.length == 1) {
+ threadName = names[0];
+ } else {
+ threadName = "";
+ }
+ Thread.currentThread().setName(threadName);
+ }
+
SessionState.detachSession();
if (ThreadWithGarbageCleanup.currentThread() instanceof ThreadWithGarbageCleanup) {
ThreadWithGarbageCleanup currentThread =