You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hive.apache.org by pa...@apache.org on 2011/03/18 08:18:09 UTC
svn commit: r1082834 - in /hive/trunk/ql/src/java/org/apache/hadoop/hive/ql:
Driver.java exec/Utilities.java
Author: pauly
Date: Fri Mar 18 07:18:08 2011
New Revision: 1082834
URL: http://svn.apache.org/viewvc?rev=1082834&view=rev
Log:
HIVE-2028 Performance instruments for client side execution (Ning Zhang via pauly)
Modified:
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
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=1082834&r1=1082833&r2=1082834&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 Fri Mar 18 07:18:08 2011
@@ -313,6 +313,9 @@ public class Driver implements CommandPr
* The SQL query to compile.
*/
public int compile(String command) {
+
+ Utilities.PerfLogBegin(LOG, "compile");
+
if (plan != null) {
close();
plan = null;
@@ -391,11 +394,14 @@ public class Driver implements CommandPr
if (HiveConf.getBoolVar(conf,
HiveConf.ConfVars.HIVE_AUTHORIZATION_ENABLED)) {
try {
+ Utilities.PerfLogBegin(LOG, "doAuthorization");
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");
}
}
@@ -418,6 +424,8 @@ public class Driver implements CommandPr
console.printError(errorMessage + "\n"
+ org.apache.hadoop.util.StringUtils.stringifyException(e));
return (12);
+ } finally {
+ Utilities.PerfLogEnd(LOG, "compile");
}
}
@@ -666,6 +674,9 @@ public class Driver implements CommandPr
* sure that the locks are lexicographically sorted.
**/
public int acquireReadWriteLocks() {
+
+ Utilities.PerfLogBegin(LOG, "acquireReadWriteLocks");
+
try {
int sleepTime = conf.getIntVar(HiveConf.ConfVars.HIVE_LOCK_SLEEP_BETWEEN_RETRIES) * 1000;
int numRetries = conf.getIntVar(HiveConf.ConfVars.HIVE_LOCK_NUMRETRIES);
@@ -764,6 +775,8 @@ public class Driver implements CommandPr
console.printError(errorMessage, "\n"
+ org.apache.hadoop.util.StringUtils.stringifyException(e));
return (10);
+ } finally {
+ Utilities.PerfLogEnd(LOG, "acquireReadWriteLocks");
}
}
@@ -787,10 +800,14 @@ public class Driver implements CommandPr
* locks have already been released, ignore them
**/
private void releaseLocks(List<HiveLock> hiveLocks) {
+ Utilities.PerfLogBegin(LOG, "releaseLocks");
+
if (hiveLocks != null) {
ctx.getHiveLockMgr().releaseLocks(hiveLocks);
}
ctx.setHiveLocks(null);
+
+ Utilities.PerfLogEnd(LOG, "releaseLocks");
}
public CommandProcessorResponse run(String command) {
@@ -798,6 +815,7 @@ public class Driver implements CommandPr
SQLState = null;
int ret = compile(command);
+
if (ret != 0) {
releaseLocks(ctx.getHiveLocks());
return new CommandProcessorResponse(ret, errorMessage, SQLState);
@@ -893,6 +911,8 @@ public class Driver implements CommandPr
}
public int execute() {
+ Utilities.PerfLogBegin(LOG, "Driver.execute");
+
boolean noName = StringUtils.isEmpty(conf.getVar(HiveConf.ConfVars.HADOOPJOBNAME));
int maxlen = conf.getIntVar(HiveConf.ConfVars.HIVEJOBNAMELENGTH);
@@ -919,10 +939,18 @@ public class Driver implements CommandPr
for (Hook peh : getPreExecHooks()) {
if (peh instanceof ExecuteWithHookContext) {
+ Utilities.PerfLogBegin(LOG, "PreHook." + peh.getClass().getSimpleName());
+
((ExecuteWithHookContext) peh).run(hookContext);
+
+ Utilities.PerfLogEnd(LOG, "PreHook." + peh.getClass().getSimpleName());
} else if (peh instanceof PreExecute) {
+ Utilities.PerfLogBegin(LOG, "PreHook." + peh.getClass().getSimpleName());
+
((PreExecute) peh).run(SessionState.get(), plan.getInputs(), plan.getOutputs(),
ShimLoader.getHadoopShims().getUGIForConf(conf));
+
+ Utilities.PerfLogEnd(LOG, "PreHook." + peh.getClass().getSimpleName());
}
}
@@ -1039,11 +1067,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());
+
((ExecuteWithHookContext) peh).run(hookContext);
+
+ Utilities.PerfLogEnd(LOG, "PostHook." + peh.getClass().getSimpleName());
} else if (peh instanceof PostExecute) {
+ Utilities.PerfLogBegin(LOG, "PostHook." + 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());
}
}
@@ -1071,6 +1107,7 @@ public class Driver implements CommandPr
if (noName) {
conf.setVar(HiveConf.ConfVars.HADOOPJOBNAME, "");
}
+ Utilities.PerfLogEnd(LOG, "Driver.execute");
}
plan.setDone();
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=1082834&r1=1082833&r2=1082834&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 Fri Mar 18 07:18:08 2011
@@ -100,8 +100,8 @@ import org.apache.hadoop.hive.ql.plan.Ma
import org.apache.hadoop.hive.ql.plan.MapredWork;
import org.apache.hadoop.hive.ql.plan.PartitionDesc;
import org.apache.hadoop.hive.ql.plan.PlanUtils;
-import org.apache.hadoop.hive.ql.plan.TableDesc;
import org.apache.hadoop.hive.ql.plan.PlanUtils.ExpressionTypes;
+import org.apache.hadoop.hive.ql.plan.TableDesc;
import org.apache.hadoop.hive.ql.stats.StatsFactory;
import org.apache.hadoop.hive.ql.stats.StatsPublisher;
import org.apache.hadoop.hive.serde.Constants;
@@ -110,8 +110,8 @@ import org.apache.hadoop.hive.serde2.Ser
import org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe;
import org.apache.hadoop.hive.shims.ShimLoader;
import org.apache.hadoop.io.SequenceFile;
-import org.apache.hadoop.io.Writable;
import org.apache.hadoop.io.SequenceFile.CompressionType;
+import org.apache.hadoop.io.Writable;
import org.apache.hadoop.io.compress.CompressionCodec;
import org.apache.hadoop.io.compress.DefaultCodec;
import org.apache.hadoop.mapred.FileOutputFormat;
@@ -1757,4 +1757,40 @@ 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);
+ }
}