在debug hive的问题时，我们经常需要在源码里面增加必要的日志信息，来跟踪变量的变化或者是方法执行的情况，性能等。。hive里面有下面几个日志的实现方式。
1种是常用的通过
|
1
|
org.apache.commons.logging.Log |
和
|
1
|
org.apache.commons.logging.LogFactory |
类实现的。
比如要打印类的info信息时，只需要下面这样就可以。
|
1
2
|
static final private Log LOG = LogFactory.getLog(CLASS_NAME)
LOG.info("xxxxxx");
|
如果要跟踪一个方法的执行时间，只需要在在方法调用前后各加一条日志信息记录当前时间戳，然后取差值即可。
另一种是LogHelper
|
1
|
org.apache.hadoop.hive.ql.session.SessionState.LogHelper |
LogHelper类是SessionState的内部类
输出日志最终调用的是LOG.xxx和对应日志输出的println方法（比如System.out.println/log4j等）
但是日志只有两个级别，info和error。
以printInfo方法为例，具体实现：
|
1
2
3
4
5
6
|
public void printInfo(String info, String detail) {
if (!getIsSilent()) {
getInfoStream().println(info);
}
LOG.info(info + StringUtils.defaultString(detail)); //调用LOG.info(即第一种方法)
}
|
使用的sample:
|
1
2
|
static final private LogHelper console = new LogHelper (LOG);
console.printError("Authorization failed:" + authExp.getMessage() + ". Use SHOW GRANT to get more details." );
|
还有一种重要的类是PerfLogger类，可以实现记录方法执行时间的信息，在一些情况下可以取代第一种记录性能的方法。
PerfLogger类主要是用在Driver类的compile方法中，用来记录各个step使用的时间。
看下具体实现：
首先声明存储starttime和endtime的map:
|
1
2
|
protected final Map<String, Long> startTimes = new HashMap<String, Long>();
protected final Map<String, Long> endTimes = new HashMap<String, Long>();
|
主要方法：
1).构造方法可以传入一个boolean参数，控制是否reset(默认是false)
|
1
2
3
4
5
6
7
8
9
10
11
|
protected static final ThreadLocal<PerfLogger> perfLogger = new ThreadLocal<PerfLogger>();
public static PerfLogger getPerfLogger(boolean resetPerfLogger) {
if (SessionState.get() == null) {
if (perfLogger.get() == null || resetPerfLogger) {
perfLogger.set(new PerfLogger());
}
return perfLogger.get();
} else {
return SessionState.get().getPerfLogger(resetPerfLogger);
}
}
|
2).PerfLogBegin 用来记录开始时间,主要是使用了LOG.info(第一种记录日志的方法)
|
1
2
3
4
5
|
public void PerfLogBegin(String callerName, String method) {
long startTime = System.currentTimeMillis();
LOG.info( "<PERFLOG method=" + method + " from=" + callerName + ">");
startTimes.put(method, new Long(startTime)); //将方法和对应的startTime放在startTimes的map中
}
|
3).相应的PerfLogEnd用来记录结束时间
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
|
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));
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).append( ">");
LOG.info(sb);
return duration;
}
|
getStartTime和getEndTime分别通过对应的map来获取starttime和endtime
4.是不是所有的method都可以用这种方法获取执行的性能？答案是no，在PerfLogger类中定义了部分属性，对应于method
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
|
public static final String ACQUIRE_READ_WRITE_LOCKS = "acquireReadWriteLocks";
public static final String COMPILE = "compile";
public static final String PARSE = "parse";
public static final String ANALYZE = "semanticAnalyze";
public static final String DO_AUTHORIZATION = "doAuthorization";
public static final String DRIVER_EXECUTE = "Driver.execute";
public static final String INPUT_SUMMARY = "getInputSummary";
public static final String GET_SPLITS = "getSplits";
public static final String RUN_TASKS = "runTasks";
public static final String SERIALIZE_PLAN = "serializePlan";
public static final String DESERIALIZE_PLAN = "deserializePlan";
public static final String CLONE_PLAN = "clonePlan";
public static final String TASK = "task.";
public static final String RELEASE_LOCKS = "releaseLocks";
public static final String PRUNE_LISTING = "prune-listing";
public static final String PARTITION_RETRIEVING = "partition-retrieving";
public static final String PRE_HOOK = "PreHook.";
public static final String POST_HOOK = "PostHook.";
public static final String FAILURE_HOOK = "FailureHook.";
public static final String DRIVER_RUN = "Driver.run";
public static final String TIME_TO_SUBMIT = "TimeToSubmit";
public static final String TEZ_SUBMIT_TO_RUNNING = "TezSubmitToRunningDag";
public static final String TEZ_BUILD_DAG = "TezBuildDag";
public static final String TEZ_SUBMIT_DAG = "TezSubmitDag";
public static final String TEZ_RUN_DAG = "TezRunDag";
public static final String TEZ_CREATE_VERTEX = "TezCreateVertex.";
public static final String TEZ_RUN_VERTEX = "TezRunVertex.";
public static final String TEZ_INITIALIZE_PROCESSOR = "TezInitializeProcessor";
public static final String TEZ_RUN_PROCESSOR = "TezRunProcessor";
public static final String TEZ_INIT_OPERATORS = "TezInitializeOperators";
public static final String LOAD_HASHTABLE = "LoadHashtable";
public static final String ORC_GET_SPLITS = "OrcGetSplits";
|
再来看一下其调用方式：
|
1
2
3
4
5
6
7
8
9
10
|
比如org.apache.hadoop.hive.ql.Driver类中的compile方法：static final private String CLASS_NAME = Driver. class.getName();
public int compile(String command, boolean resetTaskIds) {
PerfLogger perfLogger = PerfLogger.getPerfLogger(); //实例化一个PerfLogger的对象
....... perfLogger.PerfLogBegin( CLASS_NAME, PerfLogger.PARSE); //记录开始时间，传入本类的类名记录的方法（方法对应了PerfLogger类中对应的属性）
ParseDriver pd = new ParseDriver();
ASTNode tree = pd.parse(command, ctx);
tree = ParseUtils.findRootNonNullToken(tree);
perfLogger.PerfLogEnd( CLASS_NAME, PerfLogger.PARSE);
|
记录parse消耗时间的对应日志：
|
1
2
3
|
14/07/31 14:33:21 INFO log.PerfLogger: <PERFLOG method=parse from=org.apache.hadoop.hive.ql.Driver>
.....14/07/31 14:33:21 INFO log.PerfLogger: </PERFLOG method=parse start=1406788401914 end=1406788401916 duration=2 from=org.apache.hadoop.hive.ql.Driver>
|
3种方法可以根据需要选择使用。
本文转自菜菜光 51CTO博客，原文链接：http://blog.51cto.com/caiguangguang/1541771，如需转载请自行联系原作者