You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hbase.apache.org by ns...@apache.org on 2011/10/11 04:11:10 UTC

svn commit: r1181466 - /hbase/branches/0.89/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java

Author: nspiegelberg
Date: Tue Oct 11 02:11:09 2011
New Revision: 1181466

URL: http://svn.apache.org/viewvc?rev=1181466&view=rev
Log:
track slow queries

Summary:
In addition to large response, also log slow queries.

Test Plan:
Ran locally with large data. Output is something like:

WARN org.apache.hadoop.ipc.HBaseServer: IPC Server handler 23 on 46829:
(responseTooLarge) (responseTooSlow) get([B@7e350225, row=row,
maxVersions=2147483647, timeRange=[0,9223372036854775807),
families={(family=cf1, columns=ALL), (family=cf2, columns=ALL}) from
10.47.56.33:34161: Size: 47.7m: Time (ms): 2932

DiffCamp Revision: 193928
Reviewed By: kranganathan
Reviewers: nspiegelberg, kranganathan
CC: kranganathan, hbase@lists
Revert Plan:
OK

Modified:
    hbase/branches/0.89/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java

Modified: hbase/branches/0.89/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java?rev=1181466&r1=1181465&r2=1181466&view=diff
==============================================================================
--- hbase/branches/0.89/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java (original)
+++ hbase/branches/0.89/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java Tue Oct 11 02:11:09 2011
@@ -88,12 +88,17 @@ public abstract class HBaseServer {
   private static final int MAX_QUEUE_SIZE_PER_HANDLER = 100;
 
   private static final String WARN_RESPONSE_SIZE =
-      "hbase.ipc.warn.response.size";
+    "hbase.ipc.warn.response.size";
 
-  /** Default value for above param */
+  private static final String WARN_RESPONSE_TIME =
+    "hbase.ipc.warn.response.time";
+
+  /** Default value for above params */
   private static final int DEFAULT_WARN_RESPONSE_SIZE = 100 * 1024 * 1024;
+  private static final int DEFAULT_WARN_RESPONSE_TIME = 1000; // milliseconds
 
   private final int warnResponseSize;
+  private final int warnResponseTime;
 
   public static final Log LOG =
     LogFactory.getLog("org.apache.hadoop.ipc.HBaseServer");
@@ -920,7 +925,7 @@ public abstract class HBaseServer {
           String errorClass = null;
           String error = null;
           Writable value = null;
-
+          long now = System.currentTimeMillis();
           CurCall.set(call);
           UserGroupInformation previous = UserGroupInformation.getCurrentUGI();
           UserGroupInformation.setCurrentUser(call.connection.ticket);
@@ -963,13 +968,17 @@ public abstract class HBaseServer {
             WritableUtils.writeString(out, errorClass);
             WritableUtils.writeString(out, error);
           }
-
-          if (buf.size() > warnResponseSize) {
-            LOG.warn(getName()+", responseTooLarge for: "+call+": Size: "
-                     + StringUtils.humanReadableInt(buf.size()));
+          long took = System.currentTimeMillis() - now;
+          if ((buf.size() > warnResponseSize) ||
+              (took > warnResponseTime)) {
+            LOG.warn(getName() + ": "
+                + ((buf.size() > warnResponseSize) ? "(responseTooLarge) " : "")
+                + ((took > warnResponseTime) ? "(responseTooSlow) " : "")
+                + call +
+                ": Size: " + StringUtils.humanReadableInt(buf.size()) +
+                ": Time (ms): " + took);
           }
 
-
           call.setResponse(buf.getByteBuffer());
           responder.doRespond(call);
         } catch (InterruptedException e) {
@@ -1034,8 +1043,10 @@ public abstract class HBaseServer {
     this.tcpKeepAlive = conf.getBoolean("ipc.server.tcpkeepalive", true);
 
     this.warnResponseSize = conf.getInt(WARN_RESPONSE_SIZE,
-                                        DEFAULT_WARN_RESPONSE_SIZE);
+        DEFAULT_WARN_RESPONSE_SIZE);
 
+    this.warnResponseTime = conf.getInt(WARN_RESPONSE_TIME,
+        DEFAULT_WARN_RESPONSE_TIME);
 
     // Create the responder here
     responder = new Responder();