Author: liyin Date: Thu Apr 24 18:18:35 2014 New Revision: 1589819 URL: http://svn.apache.org/r1589819 Log: [HBASE-9930] Making callContext fully support profiling data in swift
Author: adela Summary: we now support profiling time on the client and on the serverside. I also refactored a little bit the unit test for Header Protocol & profiling data Test Plan: extended TestHeaderSendReceive unit test, this is how it looks like profiling data after first put: client_network_latency.ms:40, hlog_sync_time.ms:1, total_server_time.ms:5 profiling data after second put: client_network_latency.ms:3, hlog_sync_time.ms:1, total_server_time.ms:1 profiling data after get: client_network_latency.ms:3, total_server_time.ms:1 profiling data after get: client_network_latency.ms:4, total_server_time.ms:1 Reviewers: manukranthk, gauravm, fan Reviewed By: manukranthk CC: elliott, hbase-eng@ Differential Revision: https://phabricator.fb.com/D1290014 Task ID: 3573857 Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/HBaseToThriftAdapter.java hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/ThriftCallStatsReporter.java hbase/branches/0.89-fb/src/test/java/org/apache/hadoop/hbase/thrift/TestHeaderSendReceive.java Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/HBaseToThriftAdapter.java URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/HBaseToThriftAdapter.java?rev=1589819&r1=1589818&r2=1589819&view=diff ============================================================================== --- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/HBaseToThriftAdapter.java (original) +++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/HBaseToThriftAdapter.java Thu Apr 24 18:18:35 2014 @@ -51,6 +51,7 @@ import org.apache.hadoop.hbase.io.hfile. import org.apache.hadoop.hbase.ipc.HBaseRPCOptions; import org.apache.hadoop.hbase.ipc.HBaseServer.Call; import org.apache.hadoop.hbase.ipc.HRegionInterface; +import org.apache.hadoop.hbase.ipc.ProfilingData; import org.apache.hadoop.hbase.ipc.ScannerResult; import org.apache.hadoop.hbase.ipc.ThriftClientInterface; import org.apache.hadoop.hbase.ipc.ThriftHRegionInterface; @@ -58,6 +59,7 @@ import org.apache.hadoop.hbase.ipc.thrif import org.apache.hadoop.hbase.master.AssignmentPlan; import org.apache.hadoop.hbase.regionserver.HRegion; import org.apache.hadoop.hbase.util.Bytes; +import org.apache.hadoop.hbase.util.EnvironmentEdgeManager; import org.apache.hadoop.hbase.util.Pair; import org.apache.hadoop.io.BytesWritable; import org.apache.hadoop.io.LongWritable; @@ -87,6 +89,8 @@ public class HBaseToThriftAdapter implem private Class<? extends ThriftClientInterface> clazz; private HBaseRPCOptions options; private boolean useHeaderProtocol; + // start time of the call on the client side + private long startCallTimestamp; public HBaseToThriftAdapter(ThriftClientInterface connection, ThriftClientManager clientManager, @@ -101,6 +105,7 @@ public class HBaseToThriftAdapter implem this.options = options; this.useHeaderProtocol = conf.getBoolean(HConstants.USE_HEADER_PROTOCOL, HConstants.DEFAULT_USE_HEADER_PROTOCOL); + this.startCallTimestamp = -1; } /** @@ -182,6 +187,7 @@ public class HBaseToThriftAdapter implem } private void preProcess() { + this.startCallTimestamp = EnvironmentEdgeManager.currentTimeMillis(); if (this.connection == null || clientManager == null) { if (connection != null) { try { @@ -225,7 +231,11 @@ public class HBaseToThriftAdapter implem byte[] dataBytes = Bytes.string64ToBytes(dataString); try { Call call = Bytes.readThriftBytes(dataBytes, Call.class); - this.options.profilingResult = call.getProfilingData(); + ProfilingData pd = call.getProfilingData(); + pd.addLong(ProfilingData.CLIENT_NETWORK_LATENCY_MS, + EnvironmentEdgeManager.currentTimeMillis() + - this.startCallTimestamp); + this.options.profilingResult = pd; } catch (Exception e) { LOG.error("data deserialization didn't succeed", e); } Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/ThriftCallStatsReporter.java URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/ThriftCallStatsReporter.java?rev=1589819&r1=1589818&r2=1589819&view=diff ============================================================================== --- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/ThriftCallStatsReporter.java (original) +++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/thrift/ThriftCallStatsReporter.java Thu Apr 24 18:18:35 2014 @@ -265,6 +265,8 @@ public class ThriftCallStatsReporter ext Call call = HRegionServer.callContext.get(); HRegionServer.callContext.remove(); if (call != null && call.isShouldProfile()) { + call.getProfilingData().addLong(ProfilingData.TOTAL_SERVER_TIME_MS, + ctx.getProcessingTimeMs()); sendCallInfoToClient(call, ctx.requestContext); } } catch (Exception e) { Modified: hbase/branches/0.89-fb/src/test/java/org/apache/hadoop/hbase/thrift/TestHeaderSendReceive.java URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/test/java/org/apache/hadoop/hbase/thrift/TestHeaderSendReceive.java?rev=1589819&r1=1589818&r2=1589819&view=diff ============================================================================== --- hbase/branches/0.89-fb/src/test/java/org/apache/hadoop/hbase/thrift/TestHeaderSendReceive.java (original) +++ hbase/branches/0.89-fb/src/test/java/org/apache/hadoop/hbase/thrift/TestHeaderSendReceive.java Thu Apr 24 18:18:35 2014 @@ -23,28 +23,32 @@ import static org.junit.Assert.assertNul import java.io.IOException; +import junit.framework.Assert; + import org.apache.hadoop.hbase.HBaseTestingUtility; import org.apache.hadoop.hbase.HConstants; import org.apache.hadoop.hbase.client.Get; +import org.apache.hadoop.hbase.client.HBaseAdmin; import org.apache.hadoop.hbase.client.HTable; import org.apache.hadoop.hbase.client.HTableAsync; import org.apache.hadoop.hbase.client.Put; import org.apache.hadoop.hbase.ipc.ProfilingData; import org.apache.hadoop.hbase.regionserver.HRegionServer; import org.apache.hadoop.hbase.util.Bytes; -import org.junit.After; +import org.junit.AfterClass; import org.junit.Before; +import org.junit.BeforeClass; import org.junit.Test; /** - * Check whether we correctly receive profiling data with the header protocol enabled + * Check whether we correctly receive profiling data with the header protocol + * enabled * */ - public class TestHeaderSendReceive { - private final HBaseTestingUtility TEST_UTIL = new HBaseTestingUtility(); - private final int SLAVES = 1; - static final byte[] TABLE = Bytes.toBytes("testTable"); + private static HBaseTestingUtility TEST_UTIL; + private static final int SLAVES = 1; + static final byte[] TABLE1 = Bytes.toBytes("testTable"); static final byte[] FAMILY = Bytes.toBytes("family"); static final byte[][] FAMILIES = new byte[][] { FAMILY }; byte[] r1 = Bytes.toBytes("r1"); @@ -53,6 +57,19 @@ public class TestHeaderSendReceive { @Before public void setUp() throws Exception { + HBaseAdmin admin = TEST_UTIL.getHBaseAdmin(); + if (admin.tableExists(TABLE1)) { + if (admin.isTableEnabled(TABLE1)) { + admin.disableTable(TABLE1); + } + admin.deleteTable(TABLE1); + } + TEST_UTIL.createTable(TABLE1, FAMILIES); + } + + @BeforeClass + public static void setUpBeforeClass() throws Exception { + TEST_UTIL = new HBaseTestingUtility(); TEST_UTIL.getConfiguration().setBoolean( HConstants.REGION_SERVER_WRITE_THRIFT_INFO_TO_META, true); TEST_UTIL.getConfiguration().setBoolean(HConstants.CLIENT_TO_RS_USE_THRIFT, @@ -62,8 +79,8 @@ public class TestHeaderSendReceive { TEST_UTIL.startMiniCluster(SLAVES); } - @After - public void tearDown() throws Exception { + @AfterClass + public static void tearDown() throws Exception { TEST_UTIL.shutdownMiniCluster(); } @@ -72,7 +89,7 @@ public class TestHeaderSendReceive { */ @Test public void testProfilingData() throws Exception { - HTable ht = TEST_UTIL.createTable(TABLE, FAMILIES); + HTable ht = new HTable(TEST_UTIL.getConfiguration(), TABLE1); Put put = new Put(r1); put.add(FAMILY, null, value); ht.setProfiling(true); @@ -80,6 +97,9 @@ public class TestHeaderSendReceive { ProfilingData pd = ht.getProfilingData(); assertNotNull(pd); System.out.println("profiling data after first put: " + pd); + // check if we are gettng all necessary profiling params + checkProfiling(false, true, pd); + // disable profiling and check that we get no profiling data back ht.setProfiling(false); @@ -94,6 +114,7 @@ public class TestHeaderSendReceive { pd = ht.getProfilingData(); assertNotNull(pd); System.out.println("profiling data after second put: " + pd); + checkProfiling(false, true, pd); // make a get Get get = new Get.Builder(r1).addFamily(FAMILY).create(); @@ -102,13 +123,45 @@ public class TestHeaderSendReceive { pd = ht.getProfilingData(); System.out.println("profiling data after get: " + pd); assertNotNull(pd); + checkProfiling(true, false, pd); // test async get ht.setProfiling(true); - ((HTableAsync)ht).getAsync(get).get(); - pd = ht.getProfilingData(); + HTableAsync async = new HTableAsync(ht); + async.getAsync(get).get(); + pd = async.getProfilingData(); System.out.println("profiling data after get: " + pd); assertNotNull(pd); + checkProfiling(true, false, pd); + ht.close(); + } + + /** + * Check that all the necessary profiling info is in profiling data and is not + * equal to zero + * + * @param isGet + * - if the last htable operation was get + * @param isPut + * - !isGet (if the last htable operation was put + * @param pd + * - profiling data object + */ + public void checkProfiling(boolean isGet, boolean isPut, ProfilingData pd) { + assertNotNull(ProfilingData.CLIENT_NETWORK_LATENCY_MS + " is null", + pd.getLong(ProfilingData.CLIENT_NETWORK_LATENCY_MS)); + Assert.assertTrue(ProfilingData.CLIENT_NETWORK_LATENCY_MS + + " should be greater than zero", + pd.getLong(ProfilingData.CLIENT_NETWORK_LATENCY_MS) > 0); + assertNotNull(ProfilingData.TOTAL_SERVER_TIME_MS + " is null", + pd.getLong(ProfilingData.TOTAL_SERVER_TIME_MS)); + Assert.assertTrue(ProfilingData.TOTAL_SERVER_TIME_MS + + " should be greater than zero", + pd.getLong(ProfilingData.TOTAL_SERVER_TIME_MS) > 0); + if (isPut) { + assertNotNull(ProfilingData.HLOG_SYNC_TIME_MS + " is null", + pd.getLong(ProfilingData.HLOG_SYNC_TIME_MS)); + } } /** @@ -120,13 +173,14 @@ public class TestHeaderSendReceive { @Test public void testServerSideEnabledProfiling() throws IOException { HRegionServer.enableServerSideProfilingForAllCalls.set(true); - HTable ht = TEST_UTIL.createTable(TABLE, FAMILIES); + HTable ht = new HTable(TEST_UTIL.getConfiguration(), TABLE1); Put p = new Put(r1); p.add(FAMILY, null, value); ht.put(p); ProfilingData pd = ht.getProfilingData(); assertNotNull(pd); System.out.println("profiling data: " + pd); + ht.close(); } }
