[jira] [HBASE-5744] Thrift server metrics should be long instead of int

Summary:
As we measure our Thrift call latencies in nanoseconds, we need to make
latencies long instead of int everywhere. There is a bug where we truncate a
nanosecond latency to int, which is a problem with RPCs that take more than
2.147483647 seconds to process.

This is a trunk diff. The 89-fb version of this diff is at D2679.

Test Plan:
TestThriftServer is updated to test for the failure case (an RPC is artificially
made to take 3 seconds). The new test case fails without the fix.

Re-run all unit tests.

Reviewers: stack, sc, Kannan, JIRA

Reviewed By: sc

Differential Revision: https://reviews.facebook.net/D2685



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

src/main/java/org/apache/hadoop/hbase/thrift/HbaseHandlerMetricsProxy.java

@@ -65,7 +65,7 @@ public class HbaseHandlerMetricsProxy implements InvocationHandler {
     try {
       long start = now();
       result = m.invoke(handler, args);
-      int processTime = (int)(now() - start);
+      long processTime = now() - start;
       metrics.incMethodTime(m.getName(), processTime);
     } catch (InvocationTargetException e) {
       throw e.getTargetException();

src/main/java/org/apache/hadoop/hbase/thrift/ThriftMetrics.java

@@ -98,16 +98,16 @@ public class ThriftMetrics implements Updater {
     numRowKeysInBatchMutate.inc(diff);
   }
 
-  public void incMethodTime(String name, int time) {
-    MetricsTimeVaryingRate methodTimeMetrc = getMethodTimeMetrics(name);
-    if (methodTimeMetrc == null) {
+  public void incMethodTime(String name, long time) {
+    MetricsTimeVaryingRate methodTimeMetric = getMethodTimeMetrics(name);
+    if (methodTimeMetric == null) {
       LOG.warn(
           "Got incMethodTime() request for method that doesnt exist: " + name);
       return; // ignore methods that dont exist.
     }
 
     // inc method specific processTime
-    methodTimeMetrc.inc(time);
+    methodTimeMetric.inc(time);
 
     // inc general processTime
     thriftCall.inc(time);

src/test/java/org/apache/hadoop/hbase/thrift/TestThriftServer.java

@@ -40,11 +40,13 @@ import org.apache.hadoop.hbase.filter.ParseFilter;
 import org.apache.hadoop.hbase.thrift.generated.BatchMutation;
 import org.apache.hadoop.hbase.thrift.generated.ColumnDescriptor;
 import org.apache.hadoop.hbase.thrift.generated.Hbase;
+import org.apache.hadoop.hbase.thrift.generated.IOError;
 import org.apache.hadoop.hbase.thrift.generated.Mutation;
 import org.apache.hadoop.hbase.thrift.generated.TCell;
 import org.apache.hadoop.hbase.thrift.generated.TRegionInfo;
 import org.apache.hadoop.hbase.thrift.generated.TRowResult;
 import org.apache.hadoop.hbase.util.Bytes;
+import org.apache.hadoop.hbase.util.Threads;
 import org.apache.hadoop.metrics.ContextFactory;
 import org.apache.hadoop.metrics.MetricsContext;
 import org.apache.hadoop.metrics.MetricsUtil;
@@ -130,24 +132,43 @@ public class TestThriftServer {
     dropTestTables(handler);
   }
 
+  public static final class MySlowHBaseHandler extends ThriftServerRunner.HBaseHandler
+      implements Hbase.Iface {
+
+    protected MySlowHBaseHandler(Configuration c)
+        throws IOException {
+      super(c);
+    }
+
+    @Override
+    public List<ByteBuffer> getTableNames() throws IOError {
+      Threads.sleepWithoutInterrupt(3000);
+      return super.getTableNames();
+    }
+  }
+
   /**
    * Tests if the metrics for thrift handler work correctly
    */
   public void doTestThriftMetrics() throws Exception {
     Configuration conf = UTIL.getConfiguration();
     ThriftMetrics metrics = getMetrics(conf);
-    Hbase.Iface handler = getHandler(metrics, conf);
+    Hbase.Iface handler = getHandlerForMetricsTest(metrics, conf);
     createTestTables(handler);
     dropTestTables(handler);
     verifyMetrics(metrics, "createTable_num_ops", 2);
     verifyMetrics(metrics, "deleteTable_num_ops", 2);
     verifyMetrics(metrics, "disableTable_num_ops", 2);
+    handler.getTableNames(); // This will have an artificial delay.
+
+    // 3 to 6 seconds (to account for potential slowness), measured in nanoseconds.
+    verifyMetricRange(metrics, "getTableNames_avg_time", 3L * 1000 * 1000 * 1000,
+        6L * 1000 * 1000 * 1000);
   }
 
-  private static Hbase.Iface getHandler(ThriftMetrics metrics, Configuration conf)
+  private static Hbase.Iface getHandlerForMetricsTest(ThriftMetrics metrics, Configuration conf)
       throws Exception {
-    Hbase.Iface handler =
-      new ThriftServerRunner.HBaseHandler(conf);
+    Hbase.Iface handler = new MySlowHBaseHandler(conf);
     return HbaseHandlerMetricsProxy.newInstance(handler, metrics, conf);
   }
 
@@ -164,16 +185,6 @@ public class TestThriftServer {
                .createRecord(ThriftMetrics.CONTEXT_NAME).remove();
   }
 
-  private static void verifyMetrics(ThriftMetrics metrics, String name, int expectValue)
-      throws Exception {
-    MetricsContext context = MetricsUtil.getContext(
-        ThriftMetrics.CONTEXT_NAME);
-    metrics.doUpdates(context);
-    OutputRecord record = context.getAllRecords().get(
-        ThriftMetrics.CONTEXT_NAME).iterator().next();
-    assertEquals(expectValue, record.getMetric(name).intValue());
-  }
-
   public static void createTestTables(Hbase.Iface handler) throws Exception {
     // Create/enable/disable/delete tables, ensure methods act correctly
     assertEquals(handler.getTableNames().size(), 0);
@@ -201,6 +212,31 @@ public class TestThriftServer {
     assertEquals(handler.getTableNames().size(), 0);
   }
 
+  private static void verifyMetrics(ThriftMetrics metrics, String name, long expectValue)
+      throws Exception {
+    long metricVal = getMetricValue(metrics, name);
+    assertEquals(expectValue, metricVal);
+  }
+
+  private static void verifyMetricRange(ThriftMetrics metrics, String name,
+      long minValue, long maxValue)
+      throws Exception {
+    long metricVal = getMetricValue(metrics, name);
+    if (metricVal < minValue || metricVal > maxValue) {
+      throw new AssertionError("Value of metric " + name + " is outside of the expected " +
+          "range [" +  minValue + ", " + maxValue + "]: " + metricVal);
+    }
+  }
+
+  private static long getMetricValue(ThriftMetrics metrics, String name) {
+    MetricsContext context = MetricsUtil.getContext(
+        ThriftMetrics.CONTEXT_NAME);
+    metrics.doUpdates(context);
+    OutputRecord record = context.getAllRecords().get(
+        ThriftMetrics.CONTEXT_NAME).iterator().next();
+    return record.getMetric(name).longValue();
+  }
+
   /**
    * Tests adding a series of Mutations and BatchMutations, including a
    * delete mutation.  Also tests data retrieval, and getting back multiple