HBASE-4309 slow query log metrics spewing warnings

git-svn-id: https://svn.apache.org/repos/asf/hbase/trunk@1166242 13f79535-47bb-0310-9956-ffa450edef68

CHANGES.txt

@@ -240,6 +240,7 @@ Release 0.91.0 - Unreleased
    HBASE-4265  zookeeper.KeeperException$NodeExistsException if HMaster restarts
                while table is being disabled (Ming Ma)
    HBASE-4338  Package build for rpm and deb are broken (Eric Yang)
+   HBASE-4309  slow query log metrics spewing warnings (Riley Patterson)
 
   IMPROVEMENTS
    HBASE-3290  Max Compaction Size (Nicolas Spiegelberg via Stack)  

src/main/java/org/apache/hadoop/hbase/ipc/HBaseRpcMetrics.java

@@ -77,6 +77,7 @@ public class HBaseRpcMetrics implements Updater {
 
   public MetricsTimeVaryingRate rpcQueueTime = new MetricsTimeVaryingRate("RpcQueueTime", registry);
   public MetricsTimeVaryingRate rpcProcessingTime = new MetricsTimeVaryingRate("RpcProcessingTime", registry);
+  public MetricsTimeVaryingRate rpcSlowResponseTime = new MetricsTimeVaryingRate("RpcSlowResponse", registry);
 
   //public Map <String, MetricsTimeVaryingRate> metricsList = Collections.synchronizedMap(new HashMap<String, MetricsTimeVaryingRate>());
 
@@ -129,13 +130,48 @@ public class HBaseRpcMetrics implements Updater {
    *     "classname.method"
    */
   public void createMetrics(Class<?>[] ifaces, boolean prefixWithClass) {
+    createMetrics(ifaces, prefixWithClass, null);
+  }
+
+  /**
+  * Generate metrics entries for all the methods defined in the list of
+  * interfaces. A {@link MetricsTimeVaryingRate} counter will be created for
+  * each {@code Class.getMethods().getName()} entry.
+  *
+  * <p>
+  * If {@code prefixWithClass} is {@code true}, each metric will be named as
+  * {@code [Class.getSimpleName()].[Method.getName()]}. Otherwise each metric
+  * will just be named according to the method -- {@code Method.getName()}.
+  * </p>
+  *
+  * <p>
+  * Additionally, if {@code suffixes} is defined, additional metrics will be
+  * created for each method named as the original metric concatenated with
+  * the suffix.
+  * </p>
+  * @param ifaces Define metrics for all methods in the given classes
+  * @param prefixWithClass If {@code true}, each metric will be named as
+  * "classname.method"
+  * @param suffixes If not null, each method will get additional metrics ending
+  * in each of the suffixes.
+  */
+  public void createMetrics(Class<?>[] ifaces, boolean prefixWithClass,
+      String [] suffixes) {
     for (Class<?> iface : ifaces) {
       Method[] methods = iface.getMethods();
       for (Method method : methods) {
         String attrName = prefixWithClass ?
-            getMetricName(iface, method.getName()) : method.getName();
+        getMetricName(iface, method.getName()) : method.getName();
         if (get(attrName) == null)
           create(attrName);
+        if (suffixes != null) {
+          // create metrics for each requested suffix
+          for (String s : suffixes) {
+            String metricName = attrName + s;
+            if (get(metricName) == null)
+              create(metricName);
+          }
+        }
       }
     }
   }
@@ -168,4 +204,4 @@ public class HBaseRpcMetrics implements Updater {
     if (rpcStatistics != null)
       rpcStatistics.shutdown();
   }
-}
+}

src/main/java/org/apache/hadoop/hbase/ipc/WritableRpcEngine.java

@@ -264,6 +264,9 @@ class WritableRpcEngine implements RpcEngine {
     private static final int DEFAULT_WARN_RESPONSE_TIME = 10000; // milliseconds
     private static final int DEFAULT_WARN_RESPONSE_SIZE = 100 * 1024 * 1024;
 
+    /** Names for suffixed metrics */
+    private static final String ABOVE_ONE_SEC_METRIC = ".aboveOneSec.";
+
     private final int warnResponseTime;
     private final int warnResponseSize;
 
@@ -298,7 +301,8 @@ class WritableRpcEngine implements RpcEngine {
       this.ifaces = ifaces;
 
       // create metrics for the advertised interfaces this server implements.
-      this.rpcMetrics.createMetrics(this.ifaces);
+      String [] metricSuffixes = new String [] {ABOVE_ONE_SEC_METRIC};
+      this.rpcMetrics.createMetrics(this.ifaces, false, metricSuffixes);
 
       this.authorize =
         conf.getBoolean(
@@ -368,15 +372,14 @@ class WritableRpcEngine implements RpcEngine {
               startTime, processingTime, qTime, responseSize);
           // provides a count of log-reported slow responses
           if (tooSlow) {
-            rpcMetrics.inc(call.getMethodName() + ".slowResponse.",
-                processingTime);
+            rpcMetrics.rpcSlowResponseTime.inc(processingTime);
           }
         }
         if (processingTime > 1000) {
           // we use a hard-coded one second period so that we can clearly
           // indicate the time period we're warning about in the name of the 
           // metric itself
-          rpcMetrics.inc(call.getMethodName() + ".aboveOneSec.",
+          rpcMetrics.inc(call.getMethodName() + ABOVE_ONE_SEC_METRIC,
               processingTime);
         }
 
@@ -440,7 +443,7 @@ class WritableRpcEngine implements RpcEngine {
       } else if (params.length == 1 && instance instanceof HRegionServer &&
           params[0] instanceof Operation) {
         // annotate the response map with operation details
-        responseInfo.putAll(((Operation) params[1]).toMap());
+        responseInfo.putAll(((Operation) params[0]).toMap());
         // report to the log file
         LOG.warn("(operation" + tag + "): " +
             mapper.writeValueAsString(responseInfo));