You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hbase.apache.org by ga...@apache.org on 2011/08/12 06:48:24 UTC
svn commit: r1156965 - in /hbase/trunk: CHANGES.txt conf/log4j.properties
src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java
src/main/java/org/apache/hadoop/hbase/util/Objects.java
Author: garyh
Date: Fri Aug 12 04:48:24 2011
New Revision: 1156965
URL: http://svn.apache.org/viewvc?rev=1156965&view=rev
Log:
HBASE-4193 Enhance RPC debug logging with details on call contents
Added:
hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java
Modified:
hbase/trunk/CHANGES.txt
hbase/trunk/conf/log4j.properties
hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java
Modified: hbase/trunk/CHANGES.txt
URL: http://svn.apache.org/viewvc/hbase/trunk/CHANGES.txt?rev=1156965&r1=1156964&r2=1156965&view=diff
==============================================================================
--- hbase/trunk/CHANGES.txt (original)
+++ hbase/trunk/CHANGES.txt Fri Aug 12 04:48:24 2011
@@ -373,6 +373,8 @@ Release 0.91.0 - Unreleased
immediately at call return. (Vlad Dogaru via todd)
HBASE-4169 FSUtils LeaseRecovery for non HDFS FileSystems (Lohit Vijayarenu)
HBASE-3807 Fix units in RS UI metrics (subramanian raghunathan)
+ HBASE-4193 Enhance RPC debug logging to provide more details on
+ call contents
TASKS
HBASE-3559 Move report of split to master OFF the heartbeat channel
Modified: hbase/trunk/conf/log4j.properties
URL: http://svn.apache.org/viewvc/hbase/trunk/conf/log4j.properties?rev=1156965&r1=1156964&r2=1156965&view=diff
==============================================================================
--- hbase/trunk/conf/log4j.properties (original)
+++ hbase/trunk/conf/log4j.properties Fri Aug 12 04:48:24 2011
@@ -49,6 +49,9 @@ log4j.logger.org.apache.hadoop.hbase.zoo
#log4j.logger.org.apache.hadoop.dfs=DEBUG
# Set this class to log INFO only otherwise its OTT
+# Uncomment this line to enable tracing on _every_ RPC call (this can be a lot of output)
+#log4j.logger.org.apache.hadoop.ipc.HBaseServer.trace=DEBUG
+
# Uncomment the below if you want to remove logging of client region caching'
# and scan of .META. messages
# log4j.logger.org.apache.hadoop.hbase.client.HConnectionManager$HConnectionImplementation=INFO
Modified: hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
URL: http://svn.apache.org/viewvc/hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java?rev=1156965&r1=1156964&r2=1156965&view=diff
==============================================================================
--- hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java (original)
+++ hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java Fri Aug 12 04:48:24 2011
@@ -114,6 +114,8 @@ public abstract class HBaseServer implem
public static final Log LOG =
LogFactory.getLog("org.apache.hadoop.ipc.HBaseServer");
+ protected static final Log TRACELOG =
+ LogFactory.getLog("org.apache.hadoop.ipc.HBaseServer.trace");
protected static final ThreadLocal<RpcServer> SERVER =
new ThreadLocal<RpcServer>();
@@ -247,7 +249,7 @@ public abstract class HBaseServer implem
}
/** A call queued for handling. */
- private class Call implements Delayable {
+ protected class Call implements Delayable {
protected int id; // the client's call id
protected Writable param; // the parameter passed
protected Connection connection; // connection to client
@@ -1151,12 +1153,13 @@ public abstract class HBaseServer implem
}
private void processData() throws IOException, InterruptedException {
+ byte[] array = data.array();
DataInputStream dis =
- new DataInputStream(new ByteArrayInputStream(data.array()));
+ new DataInputStream(new ByteArrayInputStream(array));
int id = dis.readInt(); // try to read an id
if (LOG.isDebugEnabled())
- LOG.debug(" got #" + id);
+ LOG.debug(" got call #" + id + ", " + array.length + " bytes");
Writable param = ReflectionUtils.newInstance(paramClass, conf); // read param
param.readFields(dis);
Modified: hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java
URL: http://svn.apache.org/viewvc/hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java?rev=1156965&r1=1156964&r2=1156965&view=diff
==============================================================================
--- hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java (original)
+++ hbase/trunk/src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java Fri Aug 12 04:48:24 2011
@@ -36,6 +36,7 @@ import javax.net.SocketFactory;
import org.apache.commons.logging.*;
import org.apache.hadoop.hbase.io.HbaseObjectWritable;
+import org.apache.hadoop.hbase.util.Objects;
import org.apache.hadoop.io.*;
import org.apache.hadoop.ipc.VersionedProtocol;
import org.apache.hadoop.security.UserGroupInformation;
@@ -309,13 +310,16 @@ class WritableRpcEngine implements RpcEn
}
long startTime = System.currentTimeMillis();
- Object value = method.invoke(impl, call.getParameters());
+ Object[] params = call.getParameters();
+ Object value = method.invoke(impl, params);
int processingTime = (int) (System.currentTimeMillis() - startTime);
int qTime = (int) (startTime-receivedTime);
- if (LOG.isDebugEnabled()) {
- LOG.debug("Served: " + call.getMethodName() +
- " queueTime= " + qTime +
- " procesingTime= " + processingTime);
+ if (TRACELOG.isDebugEnabled()) {
+ TRACELOG.debug("Call #" + CurCall.get().id +
+ "; Served: " + protocol.getSimpleName()+"#"+call.getMethodName() +
+ " queueTime=" + qTime +
+ " processingTime=" + processingTime +
+ " contents=" + Objects.describeQuantity(params));
}
rpcMetrics.rpcQueueTime.inc(qTime);
rpcMetrics.rpcProcessingTime.inc(processingTime);
Added: hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java
URL: http://svn.apache.org/viewvc/hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java?rev=1156965&view=auto
==============================================================================
--- hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java (added)
+++ hbase/trunk/src/main/java/org/apache/hadoop/hbase/util/Objects.java Fri Aug 12 04:48:24 2011
@@ -0,0 +1,193 @@
+/**
+ * Copyright 2011 The Apache Software Foundation
+ *
+ * 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.hbase.util;
+
+import java.lang.reflect.Array;
+import java.util.ArrayList;
+import java.util.Arrays;
+import java.util.Collection;
+import java.util.Collections;
+import java.util.Comparator;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.NavigableSet;
+
+import org.apache.hadoop.hbase.KeyValue;
+import org.apache.hadoop.hbase.client.Action;
+import org.apache.hadoop.hbase.client.Delete;
+import org.apache.hadoop.hbase.client.Get;
+import org.apache.hadoop.hbase.client.Increment;
+import org.apache.hadoop.hbase.client.MultiAction;
+import org.apache.hadoop.hbase.client.Put;
+
+/**
+ * Utility methods for interacting with object instances.
+ */
+public class Objects {
+ private static class QuantityMap extends HashMap<String,Quantity> {
+ public void increment(String type, int count) {
+ Quantity q = get(type);
+ if (q == null) {
+ q = new Quantity();
+ q.what = type;
+ put(type, q);
+ }
+ q.increment(count);
+ }
+
+ public void stat(String type, int value) {
+ Quantity q = get(type);
+ if (q == null) {
+ q = new Stat();
+ q.what = type;
+ put(type, q);
+ }
+ q.increment(value);
+ }
+ }
+
+ private static class Quantity {
+ int count;
+ String what;
+
+ public void increment(int amount) {
+ count += amount;
+ }
+
+ public void appendToString(StringBuilder out) {
+ if (out.length() > 0) out.append(", ");
+
+ out.append(count).append(" ").append(what);
+ if (count != 1 && !what.endsWith("s")) {
+ out.append("s");
+ }
+ }
+ }
+
+ private static class Stat extends Quantity {
+ int min;
+ int max;
+ long total;
+
+ public void increment(int amount) {
+ if (count == 0) {
+ min = max = amount;
+ } else {
+ min = Math.min(min, amount);
+ max = Math.max(max, amount);
+ }
+ total += amount;
+ count++;
+ }
+
+ public void appendToString(StringBuilder out) {
+ super.appendToString(out);
+
+ out.append(" [ ");
+ if (count > 0) {
+ out.append("min=").append(min)
+ .append(" max=").append(max)
+ .append(" avg=").append((int)(total/count));
+ } else {
+ out.append("none");
+ }
+ out.append(" ]");
+ }
+ }
+
+ private static class QuantityComparator implements Comparator<Quantity> {
+ @Override
+ public int compare(Quantity q1, Quantity q2) {
+ if (q1.count < q2.count) {
+ return -1;
+ } else if (q1.count > q2.count) {
+ return 1;
+ }
+ return 0;
+ }
+ }
+
+ /**
+ * Attempts to construct a text description of the given object, by
+ * introspecting known classes and building a description of size.
+ * @param obj
+ * @return
+ */
+ public static String describeQuantity(Object obj) {
+ StringBuilder str = new StringBuilder();
+ QuantityMap quantities = new QuantityMap();
+ quantify(obj, quantities);
+ List<Quantity> totals = new ArrayList<Quantity>(quantities.values());
+ Collections.sort(totals, new QuantityComparator());
+ for (Quantity q : totals) {
+ q.appendToString(str);
+ }
+ return str.toString();
+ }
+
+ public static void quantify(Object obj, QuantityMap quantities) {
+ if (obj == null) {
+ return;
+ }
+
+ if (obj.getClass().isArray()) {
+ Class type = obj.getClass().getComponentType();
+ int length = Array.getLength(obj);
+ if (type.isPrimitive()) {
+ quantities.increment(type.getSimpleName(), length);
+ } else {
+ for (int i=0; i<length; i++) {
+ quantify(Array.get(obj, i), quantities);
+ }
+ }
+ } else if (obj instanceof Iterable) {
+ for (Object child : ((Iterable)obj)) {
+ quantify(child, quantities);
+ }
+ } else if (obj instanceof MultiAction) {
+ MultiAction multi = (MultiAction)obj;
+ quantify(multi.allActions(), quantities);
+ } else if (obj instanceof Action) {
+ quantify(((Action)obj).getAction(), quantities);
+ } else if (obj instanceof Put) {
+ quantities.increment("Put", 1);
+ quantities.increment("KeyValue", ((Put)obj).size());
+ for (List<KeyValue> keyValues : ((Put)obj).getFamilyMap().values()) {
+ for (KeyValue kv : keyValues) {
+ quantities.stat("values", kv.getValueLength());
+ }
+ }
+ } else if (obj instanceof Delete) {
+ quantities.increment("Delete", 1);
+ for (List<KeyValue> kvs : ((Delete)obj).getFamilyMap().values()) {
+ quantities.increment("KeyValue", kvs.size());
+ }
+ } else if (obj instanceof Increment) {
+ quantities.increment("Increment", 1);
+ quantities.increment("KeyValue", ((Increment)obj).numColumns());
+ } else if (obj instanceof Get) {
+ quantities.increment("Get", 1);
+ } else {
+ String type = obj.getClass().getSimpleName();
+ quantities.increment(type, 1);
+ }
+ }
+}