You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hive.apache.org by nz...@apache.org on 2011/08/14 15:48:34 UTC
svn commit: r1157532 - in /hive/trunk:
common/src/java/org/apache/hadoop/hive/conf/ conf/
ql/src/java/org/apache/hadoop/hive/ql/
ql/src/java/org/apache/hadoop/hive/ql/exec/
ql/src/java/org/apache/hadoop/hive/ql/log/
ql/src/java/org/apache/hadoop/hive/q...
Author: nzhang
Date: Sun Aug 14 13:48:33 2011
New Revision: 1157532
URL: http://svn.apache.org/viewvc?rev=1157532&view=rev
Log:
HIVE-2364. Make performance logging configurable. (Kevin Wilfong via Ning Zhang)
Added:
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
Modified:
hive/trunk/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java
hive/trunk/conf/hive-default.xml
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/exec/Utilities.java
hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/optimizer/ppr/PartitionPruner.java
Modified: hive/trunk/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java
URL: http://svn.apache.org/viewvc/hive/trunk/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java?rev=1157532&r1=1157531&r2=1157532&view=diff
==============================================================================
--- hive/trunk/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java (original)
+++ hive/trunk/common/src/java/org/apache/hadoop/hive/conf/HiveConf.java Sun Aug 14 13:48:33 2011
@@ -460,6 +460,10 @@ public class HiveConf extends Configurat
HIVE_MAPPER_CANNOT_SPAN_MULTIPLE_PARTITIONS("hive.mapper.cannot.span.multiple.partitions", false),
HIVE_REWORK_MAPREDWORK("hive.rework.mapredwork", false),
HIVE_CONCATENATE_CHECK_INDEX ("hive.exec.concatenate.check.index", true),
+
+ // The class responsible for logging client side performance metrics
+ // Must be a subclass of org.apache.hadoop.hive.ql.log.PerfLogger
+ HIVE_PERF_LOGGER("hive.exec.perf.logger", "org.apache.hadoop.hive.ql.log.PerfLogger"),
;
public final String varname;
Modified: hive/trunk/conf/hive-default.xml
URL: http://svn.apache.org/viewvc/hive/trunk/conf/hive-default.xml?rev=1157532&r1=1157531&r2=1157532&view=diff
==============================================================================
--- hive/trunk/conf/hive-default.xml (original)
+++ hive/trunk/conf/hive-default.xml Sun Aug 14 13:48:33 2011
@@ -1144,4 +1144,10 @@
by record readers</description>
</property>
+<property>
+ <name>hive.exec.perf.logger</name>
+ <value>org.apache.hadoop.hive.ql.log.PerfLogger</value>
+ <description>The class responsible logging client side performance metrics. Must be a subclass of org.apache.hadoop.hive.ql.log.PerfLogger</description>
+</property>
+
</configuration>
Modified: hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/Driver.java
URL: http://svn.apache.org/viewvc/hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/Driver.java?rev=1157532&r1=1157531&r2=1157532&view=diff
==============================================================================
--- hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/Driver.java (original)
+++ hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/Driver.java Sun Aug 14 13:48:33 2011
@@ -70,6 +70,7 @@ import org.apache.hadoop.hive.ql.lockmgr
import org.apache.hadoop.hive.ql.lockmgr.HiveLockObject;
import org.apache.hadoop.hive.ql.lockmgr.LockException;
import org.apache.hadoop.hive.ql.lockmgr.HiveLockObject.HiveLockObjectData;
+import org.apache.hadoop.hive.ql.log.PerfLogger;
import org.apache.hadoop.hive.ql.metadata.AuthorizationException;
import org.apache.hadoop.hive.ql.metadata.DummyPartition;
import org.apache.hadoop.hive.ql.metadata.Hive;
@@ -389,8 +390,9 @@ public class Driver implements CommandPr
* @return
*/
public int compile(String command, boolean resetTaskIds) {
+ PerfLogger perfLogger = PerfLogger.getPerfLogger();
+ perfLogger.PerfLogBegin(LOG, PerfLogger.COMPILE);
- Utilities.PerfLogBegin(LOG, "compile");
//holder for parent command type/string when executing reentrant queries
QueryState queryState = new QueryState();
@@ -476,14 +478,14 @@ public class Driver implements CommandPr
if (HiveConf.getBoolVar(conf,
HiveConf.ConfVars.HIVE_AUTHORIZATION_ENABLED)) {
try {
- Utilities.PerfLogBegin(LOG, "doAuthorization");
+ perfLogger.PerfLogBegin(LOG, PerfLogger.DO_AUTHORIZATION);
doAuthorization(sem);
} catch (AuthorizationException authExp) {
console.printError("Authorization failed:" + authExp.getMessage()
+ ". Use show grant to get more details.");
return 403;
} finally {
- Utilities.PerfLogEnd(LOG, "doAuthorization");
+ perfLogger.PerfLogEnd(LOG, PerfLogger.DO_AUTHORIZATION);
}
}
@@ -509,8 +511,8 @@ public class Driver implements CommandPr
+ org.apache.hadoop.util.StringUtils.stringifyException(e));
return (12);
} finally {
+ perfLogger.PerfLogEnd(LOG, PerfLogger.COMPILE);
restoreSession(queryState);
- Utilities.PerfLogEnd(LOG, "compile");
}
}
@@ -759,8 +761,8 @@ public class Driver implements CommandPr
* sure that the locks are lexicographically sorted.
**/
public int acquireReadWriteLocks() {
-
- Utilities.PerfLogBegin(LOG, "acquireReadWriteLocks");
+ PerfLogger perfLogger = PerfLogger.getPerfLogger();
+ perfLogger.PerfLogBegin(LOG, PerfLogger.ACQUIRE_READ_WRITE_LOCKS);
try {
int sleepTime = conf.getIntVar(HiveConf.ConfVars.HIVE_LOCK_SLEEP_BETWEEN_RETRIES) * 1000;
@@ -855,7 +857,7 @@ public class Driver implements CommandPr
+ org.apache.hadoop.util.StringUtils.stringifyException(e));
return (10);
} finally {
- Utilities.PerfLogEnd(LOG, "acquireReadWriteLocks");
+ perfLogger.PerfLogEnd(LOG, PerfLogger.ACQUIRE_READ_WRITE_LOCKS);
}
}
@@ -879,19 +881,22 @@ public class Driver implements CommandPr
* locks have already been released, ignore them
**/
private void releaseLocks(List<HiveLock> hiveLocks) {
- Utilities.PerfLogBegin(LOG, "releaseLocks");
+ PerfLogger perfLogger = PerfLogger.getPerfLogger();
+ perfLogger.PerfLogBegin(LOG, PerfLogger.RELEASE_LOCKS);
if (hiveLocks != null) {
ctx.getHiveLockMgr().releaseLocks(hiveLocks);
}
ctx.setHiveLocks(null);
- Utilities.PerfLogEnd(LOG, "releaseLocks");
+ perfLogger.PerfLogEnd(LOG, PerfLogger.RELEASE_LOCKS);
}
public CommandProcessorResponse run(String command) throws CommandNeedRetryException {
errorMessage = null;
SQLState = null;
+ // Reset the perf logger
+ PerfLogger.getPerfLogger(true);
int ret = compile(command);
if (ret != 0) {
@@ -1044,7 +1049,8 @@ public class Driver implements CommandPr
}
public int execute() throws CommandNeedRetryException {
- Utilities.PerfLogBegin(LOG, "Driver.execute");
+ PerfLogger perfLogger = PerfLogger.getPerfLogger();
+ perfLogger.PerfLogBegin(LOG, PerfLogger.DRIVER_EXECUTE);
boolean noName = StringUtils.isEmpty(conf.getVar(HiveConf.ConfVars.HADOOPJOBNAME));
int maxlen = conf.getIntVar(HiveConf.ConfVars.HIVEJOBNAMELENGTH);
@@ -1073,18 +1079,18 @@ public class Driver implements CommandPr
for (Hook peh : getPreExecHooks()) {
if (peh instanceof ExecuteWithHookContext) {
- Utilities.PerfLogBegin(LOG, "PreHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogBegin(LOG, PerfLogger.PRE_HOOK + peh.getClass().getSimpleName());
((ExecuteWithHookContext) peh).run(hookContext);
- Utilities.PerfLogEnd(LOG, "PreHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogEnd(LOG, PerfLogger.PRE_HOOK + peh.getClass().getSimpleName());
} else if (peh instanceof PreExecute) {
- Utilities.PerfLogBegin(LOG, "PreHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogBegin(LOG, PerfLogger.PRE_HOOK + peh.getClass().getSimpleName());
((PreExecute) peh).run(SessionState.get(), plan.getInputs(), plan.getOutputs(),
ShimLoader.getHadoopShims().getUGIForConf(conf));
- Utilities.PerfLogEnd(LOG, "PreHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogEnd(LOG, PerfLogger.PRE_HOOK + peh.getClass().getSimpleName());
}
}
@@ -1164,11 +1170,11 @@ public class Driver implements CommandPr
hookContext.setHookType(HookContext.HookType.ON_FAILURE_HOOK);
// Get all the failure execution hooks and execute them.
for (Hook ofh : getOnFailureHooks()) {
- Utilities.PerfLogBegin(LOG, "FailureHook." + ofh.getClass().getSimpleName());
+ perfLogger.PerfLogBegin(LOG, PerfLogger.FAILURE_HOOK + ofh.getClass().getSimpleName());
((ExecuteWithHookContext) ofh).run(hookContext);
- Utilities.PerfLogEnd(LOG, "FailureHook." + ofh.getClass().getSimpleName());
+ perfLogger.PerfLogEnd(LOG, PerfLogger.FAILURE_HOOK + ofh.getClass().getSimpleName());
}
// TODO: This error messaging is not very informative. Fix that.
@@ -1223,19 +1229,19 @@ public class Driver implements CommandPr
// Get all the post execution hooks and execute them.
for (Hook peh : getPostExecHooks()) {
if (peh instanceof ExecuteWithHookContext) {
- Utilities.PerfLogBegin(LOG, "PostHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogBegin(LOG, PerfLogger.POST_HOOK + peh.getClass().getSimpleName());
((ExecuteWithHookContext) peh).run(hookContext);
- Utilities.PerfLogEnd(LOG, "PostHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogEnd(LOG, PerfLogger.POST_HOOK + peh.getClass().getSimpleName());
} else if (peh instanceof PostExecute) {
- Utilities.PerfLogBegin(LOG, "PostHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogBegin(LOG, PerfLogger.POST_HOOK + peh.getClass().getSimpleName());
((PostExecute) peh).run(SessionState.get(), plan.getInputs(), plan.getOutputs(),
(SessionState.get() != null ? SessionState.get().getLineageState().getLineageInfo()
: null), ShimLoader.getHadoopShims().getUGIForConf(conf));
- Utilities.PerfLogEnd(LOG, "PostHook." + peh.getClass().getSimpleName());
+ perfLogger.PerfLogEnd(LOG, PerfLogger.POST_HOOK + peh.getClass().getSimpleName());
}
}
@@ -1266,7 +1272,7 @@ public class Driver implements CommandPr
if (noName) {
conf.setVar(HiveConf.ConfVars.HADOOPJOBNAME, "");
}
- Utilities.PerfLogEnd(LOG, "Driver.execute");
+ perfLogger.PerfLogEnd(LOG, PerfLogger.DRIVER_EXECUTE);
if (SessionState.get().getLastMapRedStatsList() != null
&& SessionState.get().getLastMapRedStatsList().size() > 0) {
Modified: hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/exec/Utilities.java
URL: http://svn.apache.org/viewvc/hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/exec/Utilities.java?rev=1157532&r1=1157531&r2=1157532&view=diff
==============================================================================
--- hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/exec/Utilities.java (original)
+++ hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/exec/Utilities.java Sun Aug 14 13:48:33 2011
@@ -2004,42 +2004,6 @@ public final class Utilities {
return false;
}
- private static ThreadLocal<Map<String, Long>> perfKeyMaps = new ThreadLocal<Map<String, Long>>();
-
- /**
- * Call this function when you start to measure time spent by a piece of code.
- * @param _log the logging object to be used.
- * @param method method or ID that identifies this perf log element.
- */
- public static void PerfLogBegin(Log _log, String method) {
- long startTime = System.currentTimeMillis();
- _log.info("<PERFLOG method=" + method + ">");
- if (perfKeyMaps.get() == null) {
- perfKeyMaps.set(new HashMap<String, Long>());
- }
- perfKeyMaps.get().put(method, new Long(startTime));
- }
-
- /**
- * Call this function in correspondence of PerfLogBegin to mark the end of the measurement.
- * @param _log
- * @param method
- */
- public static void PerfLogEnd(Log _log, String method) {
- Long startTime = perfKeyMaps.get().get(method);
- long endTime = System.currentTimeMillis();
- StringBuilder sb = new StringBuilder("</PERFLOG method=").append(method);
- if (startTime != null) {
- sb.append(" start=").append(startTime);
- }
- sb.append(" end=").append(endTime);
- if (startTime != null) {
- sb.append(" duration=").append(endTime - startTime.longValue());
- }
- sb.append(">");
- _log.info(sb);
- }
-
/**
* The check here is kind of not clean. It first use a for loop to go through
* all input formats, and choose the ones that extend ReworkMapredInputFormat
Added: hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java
URL: http://svn.apache.org/viewvc/hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java?rev=1157532&view=auto
==============================================================================
--- hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java (added)
+++ hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/log/PerfLogger.java Sun Aug 14 13:48:33 2011
@@ -0,0 +1,124 @@
+/**
+ * Licensed to the Apache Software Foundation (ASF) under one
+ * or more contributor license agreements. See the NOTICE file
+ * distributed with this work for additional information
+ * regarding copyright ownership. The ASF licenses this file
+ * to you under the Apache License, Version 2.0 (the
+ * "License"); you may not use this file except in compliance
+ * with the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.hadoop.hive.ql.log;
+
+import java.util.HashMap;
+import java.util.Map;
+
+import org.apache.commons.logging.Log;
+import org.apache.commons.logging.LogFactory;
+import org.apache.hadoop.hive.conf.HiveConf;
+import org.apache.hadoop.hive.conf.HiveConf.ConfVars;
+import org.apache.hadoop.hive.ql.session.SessionState;
+import org.apache.hadoop.util.ReflectionUtils;
+
+/**
+ * PerfLogger.
+ *
+ * Can be used to measure and log the time spent by a piece of code.
+ */
+public class PerfLogger {
+ public static final String ACQUIRE_READ_WRITE_LOCKS = "acquireReadWriteLocks";
+ public static final String COMPILE = "compile";
+ public static final String DO_AUTHORIZATION = "doAuthorization";
+ public static final String DRIVER_EXECUTE = "Driver.execute";
+ 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.";
+
+ protected static final ThreadLocal<PerfLogger> perfLogger = new ThreadLocal<PerfLogger>();
+
+ protected final Map<String, Long> perfKeyMaps = new HashMap<String, Long>();
+
+ static final private Log LOG = LogFactory.getLog(PerfLogger.class.getName());
+
+ protected PerfLogger() {
+ // Use getPerfLogger to get an instance of PerfLogger
+ }
+
+ public static PerfLogger getPerfLogger() {
+ return getPerfLogger(false);
+ }
+
+ /**
+ * Call this function to get an instance of PerfLogger.
+ *
+ * Use resetPerfLogger to require a new instance. Useful at the beginning of execution.
+ *
+ * @return Tries to return an instance of the class whose name is configured in
+ * hive.exec.perf.logger, but if it can't it just returns an instance of
+ * the base PerfLogger class
+ */
+ public static PerfLogger getPerfLogger(boolean resetPerfLogger) {
+ if (perfLogger.get() == null || resetPerfLogger) {
+ if (SessionState.get() == null) {
+ perfLogger.set(new PerfLogger());
+ } else {
+ HiveConf conf = SessionState.get().getConf();
+ try {
+ perfLogger.set((PerfLogger) ReflectionUtils.newInstance(conf.getClassByName(
+ conf.getVar(ConfVars.HIVE_PERF_LOGGER)), conf));
+ } catch (ClassNotFoundException e) {
+ LOG.error("Performance Logger Class not found:" + e.getMessage());
+ perfLogger.set(new PerfLogger());
+ }
+ }
+ }
+ return perfLogger.get();
+ }
+
+ /**
+ * Call this function when you start to measure time spent by a piece of code.
+ * @param _log the logging object to be used.
+ * @param method method or ID that identifies this perf log element.
+ */
+ public void PerfLogBegin(Log _log, String method) {
+ long startTime = System.currentTimeMillis();
+ _log.info("<PERFLOG method=" + method + ">");
+ perfKeyMaps.put(method, new Long(startTime));
+ }
+
+ /**
+ * Call this function in correspondence of PerfLogBegin to mark the end of the measurement.
+ * @param _log
+ * @param method
+ * @return long duration the difference between now and startTime, or -1 if startTime is null
+ */
+ public long PerfLogEnd(Log _log, String method) {
+ Long startTime = perfKeyMaps.get(method);
+ long endTime = System.currentTimeMillis();
+ long duration = -1;
+ 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(">");
+ _log.info(sb);
+
+ return duration;
+ }
+}
Modified: hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/optimizer/ppr/PartitionPruner.java
URL: http://svn.apache.org/viewvc/hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/optimizer/ppr/PartitionPruner.java?rev=1157532&r1=1157531&r2=1157532&view=diff
==============================================================================
--- hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/optimizer/ppr/PartitionPruner.java (original)
+++ hive/trunk/ql/src/java/org/apache/hadoop/hive/ql/optimizer/ppr/PartitionPruner.java Sun Aug 14 13:48:33 2011
@@ -44,6 +44,7 @@ import org.apache.hadoop.hive.ql.lib.Nod
import org.apache.hadoop.hive.ql.lib.NodeProcessor;
import org.apache.hadoop.hive.ql.lib.Rule;
import org.apache.hadoop.hive.ql.lib.RuleRegExp;
+import org.apache.hadoop.hive.ql.log.PerfLogger;
import org.apache.hadoop.hive.ql.metadata.Hive;
import org.apache.hadoop.hive.ql.metadata.HiveException;
import org.apache.hadoop.hive.ql.metadata.Partition;
@@ -320,7 +321,9 @@ public class PartitionPruner implements
List<String> trueNames = null;
List<String> unknNames = null;
- Utilities.PerfLogBegin(LOG, "prune-listing");
+ PerfLogger perfLogger = PerfLogger.getPerfLogger();
+
+ perfLogger.PerfLogBegin(LOG, PerfLogger.PRUNE_LISTING);
List<String> partNames = Hive.get().getPartitionNames(tab.getDbName(),
tab.getTableName(), (short) -1);
@@ -366,9 +369,9 @@ public class PartitionPruner implements
LOG.debug("retained partition: " + partName);
}
}
- Utilities.PerfLogEnd(LOG, "prune-listing");
+ perfLogger.PerfLogEnd(LOG, PerfLogger.PRUNE_LISTING);
- Utilities.PerfLogBegin(LOG, "partition-retrieving");
+ perfLogger.PerfLogBegin(LOG, PerfLogger.PARTITION_RETRIEVING);
if (trueNames != null) {
List<Partition> parts = Hive.get().getPartitionsByNames(tab, trueNames);
true_parts.addAll(parts);
@@ -377,7 +380,7 @@ public class PartitionPruner implements
List<Partition> parts = Hive.get().getPartitionsByNames(tab, unknNames);
unkn_parts.addAll(parts);
}
- Utilities.PerfLogEnd(LOG, "partition-retrieving");
+ perfLogger.PerfLogEnd(LOG, PerfLogger.PARTITION_RETRIEVING);
}
/**