You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hbase.apache.org by mb...@apache.org on 2012/10/20 14:53:01 UTC
svn commit: r1400433 - in
/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase:
io/hfile/HFileBlock.java io/hfile/HFileReaderV2.java ipc/HBaseRPC.java
ipc/HBaseServer.java ipc/ProfilingData.java regionserver/HRegionServer.java
Author: mbautin
Date: Sat Oct 20 12:53:00 2012
New Revision: 1400433
URL: http://svn.apache.org/viewvc?rev=1400433&view=rev
Log:
[0.89-fb] [HBASE-6857] Instrument read blocks
Author: aaiyer
Summary:
Instrument read blocks to check for the time we spend for loading
fs blocks for slow queries.
going to commit this to a private branch.
Test Plan:
run and collect stats
Pushed to the dev cluster. Output of the form:
2012-10-12 12:18:24,772 WARN org.apache.hadoop.hbase.ipc.HBaseServer: (operationTooSlow): {"processingtimems":24,"client":"10.159.9.23:58224","timeRange":[0,9223372036854775807],"starttimems":1350069504748,"responsesize":115330,"class":"HRegionServer","table":"loadtest","families":{"test_cf":["ALL"]},"row":"69cb3ea317a32c4e6143e665fdb20b14-402","queuetimems":0,"profilingData":"rpc_method_name:get, block_hit_cnt.INDEX.test_cf:7, block_miss_cnt.DATA.test_cf:3, block_hit_cnt.DATA.test_cf:6, total_fs_block_read_time.ns:3385612, block_miss_on_disk_size.DATA.test_cf:198491, total_fs_block_read_cnt:3, fs_block_read_time.ns: [<16384:2, <32768:1, ], hfile_block_p_read_time_ms: [<2:3, ]","method":"get","totalColumns":1,"maxVersions":1,"storeLimit":-1}
Reviewers: kranganathan, liyintang, kannan
Reviewed By: kranganathan
CC: hbase-eng@, cjin, mbautin, kannan, liujiakai, liyintang
Differential Revision: https://phabricator.fb.com/D584997
Modified:
hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java
hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseRPC.java
hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/ProfilingData.java
hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionServer.java
Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java?rev=1400433&r1=1400432&r2=1400433&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileBlock.java Sat Oct 20 12:53:00 2012
@@ -38,10 +38,14 @@ import org.apache.hadoop.fs.FSDataOutput
import org.apache.hadoop.fs.Path;
import org.apache.hadoop.hbase.io.encoding.DataBlockEncoding;
import org.apache.hadoop.hbase.io.hfile.Compression.Algorithm;
+import org.apache.hadoop.hbase.ipc.HBaseServer.Call;
+import org.apache.hadoop.hbase.ipc.ProfilingData;
+import org.apache.hadoop.hbase.regionserver.HRegionServer;
import org.apache.hadoop.hbase.regionserver.MemStore;
import org.apache.hadoop.hbase.regionserver.metrics.SchemaConfigured;
import org.apache.hadoop.hbase.util.Bytes;
import org.apache.hadoop.hbase.util.ClassSize;
+import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
import org.apache.hadoop.hbase.util.Pair;
import org.apache.hadoop.io.IOUtils;
import org.apache.hadoop.io.Writable;
@@ -1058,12 +1062,23 @@ public class HFileBlock extends SchemaCo
"-byte array at offset " + destOffset);
}
+ Call callContext = HRegionServer.callContext.get();
+ ProfilingData pData = (callContext == null)? null : callContext.getProfilingData();
+
+ long t0, t1;
+ long timeToGrabLock, timeToSeek, timeToRead, timeToReadExtra;
if (pread) {
// Positional read. Better for random reads.
int extraSize = peekIntoNextBlock ? HEADER_SIZE : 0;
+ t0 = EnvironmentEdgeManager.currentTimeMillis();
numPositionalRead.incrementAndGet();
int ret = istream.read(fileOffset, dest, destOffset, size + extraSize);
+ if (pData != null) {
+ t1 = EnvironmentEdgeManager.currentTimeMillis();
+ timeToRead = t1 - t0;
+ pData.addToHist(ProfilingData.HFILE_BLOCK_P_READ_TIME_MS, timeToRead);
+ }
if (ret < size) {
throw new IOException("Positional read of " + size + " bytes " +
"failed at offset " + fileOffset + " (returned " + ret + ")");
@@ -1075,10 +1090,22 @@ public class HFileBlock extends SchemaCo
}
} else {
+ t0 = EnvironmentEdgeManager.currentTimeMillis();
// Seek + read. Better for scanning.
synchronized (istream) {
+ if (pData != null) {
+ t1 = EnvironmentEdgeManager.currentTimeMillis();
+ timeToGrabLock = t1 - t0;
+ t0 = t1;
+ pData.addToHist(ProfilingData.HFILE_BLOCK_WAIT_FOR_LOCK_TIME_MS, timeToGrabLock);
+ }
numSeekRead.incrementAndGet();
istream.seek(fileOffset);
+ if (pData != null) {
+ t1 = EnvironmentEdgeManager.currentTimeMillis();
+ timeToSeek = t1 - t0;
+ pData.addToHist(ProfilingData.HFILE_BLOCK_SEEK_TIME_MS, timeToSeek);
+ }
long realOffset = istream.getPos();
if (realOffset != fileOffset) {
@@ -1088,12 +1115,24 @@ public class HFileBlock extends SchemaCo
}
if (!peekIntoNextBlock) {
+ t0 = EnvironmentEdgeManager.currentTimeMillis();
IOUtils.readFully(istream, dest, destOffset, size);
+ if (pData != null) {
+ t1 = EnvironmentEdgeManager.currentTimeMillis();
+ timeToRead = t1 - t0;
+ pData.addToHist(ProfilingData.HFILE_BLOCK_NO_P_READ_TIME_MS, timeToRead);
+ }
return -1;
}
// Try to read the next block header.
+ t0 = EnvironmentEdgeManager.currentTimeMillis();
if (!readWithExtra(istream, dest, destOffset, size, HEADER_SIZE))
+ if (pData != null) {
+ t1 = EnvironmentEdgeManager.currentTimeMillis();
+ timeToReadExtra = t1 - t0;
+ pData.addToHist(ProfilingData.HFILE_BLOCK_NO_P_READ_TIME_EXTRA_MS, timeToReadExtra);
+ }
return -1;
}
}
Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java?rev=1400433&r1=1400432&r2=1400433&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/io/hfile/HFileReaderV2.java Sat Oct 20 12:53:00 2012
@@ -42,6 +42,7 @@ import org.apache.hadoop.hbase.ipc.HBase
import org.apache.hadoop.hbase.ipc.ProfilingData;
import org.apache.hadoop.hbase.regionserver.HRegionServer;
import org.apache.hadoop.hbase.util.Bytes;
+import org.apache.hadoop.hbase.util.EnvironmentEdgeManager;
import org.apache.hadoop.hbase.util.IdLock;
import org.apache.hadoop.io.WritableUtils;
@@ -328,6 +329,9 @@ public class HFileReaderV2 extends Abstr
}
Call call = HRegionServer.callContext.get();
ProfilingData pData = call == null ? null : call.getProfilingData();
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("Read a block from FS. took " + (deltaNs) + " ns. For call " + call);
+ }
if (pData != null) {
pData.incInt(ProfilingData.blockMissCntStr(
hfileBlock.getBlockType().getCategory(),
@@ -337,7 +341,13 @@ public class HFileReaderV2 extends Abstr
hfileBlock.getBlockType().getCategory(),
hfileBlock.getColumnFamilyName()),
onDiskBlockSize);
- pData.incLong(ProfilingData.TOTAL_BLOCK_READ_TIME_NS, deltaNs);
+ pData.incLong(ProfilingData.TOTAL_FS_BLOCK_READ_TIME_NS, deltaNs);
+ pData.addToHist(ProfilingData.FS_BLOCK_READ_TIME_NS, deltaNs);
+ // increment the count
+ pData.incLong(ProfilingData.TOTAL_FS_BLOCK_READ_CNT, 1);
+ if (LOG.isTraceEnabled()) {
+ LOG.trace("Read a block from FS. took " + (deltaNs) + " ns. For call " + call);
+ }
}
return hfileBlock;
} finally {
Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseRPC.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseRPC.java?rev=1400433&r1=1400432&r2=1400433&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseRPC.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseRPC.java Sat Oct 20 12:53:00 2012
@@ -666,6 +666,13 @@ public class HBaseRPC {
responseInfo.put("client", clientAddress);
responseInfo.put("class", instance.getClass().getSimpleName());
responseInfo.put("method", call.getMethodName());
+
+ Call callContext = HRegionServer.callContext.get();
+ ProfilingData pData = callContext == null ? null : callContext.getProfilingData();
+ if (pData != null) {
+ responseInfo.put("profilingData", pData.toString());
+ }
+
if (params.length == 2 && instance instanceof HRegionServer &&
params[0] instanceof byte[] &&
params[1] instanceof Operation) {
Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java?rev=1400433&r1=1400432&r2=1400433&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/HBaseServer.java Sat Oct 20 12:53:00 2012
@@ -1226,7 +1226,8 @@ public abstract class HBaseServer {
String error = null;
Writable value = null;
- if (call.shouldProfile) {
+ if (HRegionServer.enableServerSideProfilingForAllCalls
+ || call.shouldProfile) {
call.profilingData = new ProfilingData ();
} else {
call.profilingData = null;
@@ -1249,7 +1250,8 @@ public abstract class HBaseServer {
UserGroupInformation.setCurrentUser(previous);
CurCall.set(null);
- if (call.shouldProfile) {
+ if (HRegionServer.enableServerSideProfilingForAllCalls
+ || call.shouldProfile) {
call.profilingData.addLong(
ProfilingData.TOTAL_SERVER_TIME_MS, total);
}
Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/ProfilingData.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/ProfilingData.java?rev=1400433&r1=1400432&r2=1400433&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/ProfilingData.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/ipc/ProfilingData.java Sat Oct 20 12:53:00 2012
@@ -4,6 +4,7 @@ import java.io.DataInput;
import java.io.DataOutput;
import java.io.IOException;
import java.util.HashMap;
+import java.util.List;
import java.util.Map;
import org.apache.commons.lang.mutable.MutableFloat;
@@ -55,7 +56,9 @@ public class ProfilingData implements Wr
/**
* total time spent reading data blocks into cache on misses
*/
- public static final String TOTAL_BLOCK_READ_TIME_NS = "total_block_read_time.ns";
+ public static final String TOTAL_FS_BLOCK_READ_TIME_NS = "total_fs_block_read_time.ns";
+ public static final String TOTAL_FS_BLOCK_READ_CNT = "total_fs_block_read_cnt";
+ public static final String FS_BLOCK_READ_TIME_NS = "fs_block_read_time.ns";
/**
* time spend writing to HLog
@@ -77,31 +80,60 @@ public class ProfilingData implements Wr
*/
public static final String RPC_METHOD_NAME = "rpc_method_name";
+ public static final String HFILE_BLOCK_NO_P_READ_TIME_MS = "hfile_block_no_p_read_time_ms";
+ public static final String HFILE_BLOCK_NO_P_READ_TIME_EXTRA_MS = "hfile_block_no_p_read_time_extra_ms";
+ public static final String HFILE_BLOCK_P_READ_TIME_MS = "hfile_block_p_read_time_ms";
+ public static final String HFILE_BLOCK_SEEK_TIME_MS = "hfile_block_seek_time_ms";
+ public static final String HFILE_BLOCK_WAIT_FOR_LOCK_TIME_MS = "hfile_block_wait_for_lock_time_ms";
+
/**
* separator used when concatenating strings to be merged
*/
public static final String STRING_MERGE_SEPARATOR = ",";
- private Map<String, String> mapString = new HashMap<String, String>();
- private Map<String, MutableLong> mapLong = new HashMap<String, MutableLong>();
- private Map<String, MutableInt> mapInt = new HashMap<String, MutableInt>();
- private Map<String, Boolean> mapBoolean = new HashMap<String, Boolean>();
- private Map<String, MutableFloat> mapFloat = new HashMap<String, MutableFloat>();
-
- public ProfilingData() {}
-
- public void addString(String key, String val) {
- mapString.put(key, val);
- }
-
- public String getString(String key) {
- return mapString.get(key);
- }
-
- public void addLong(String key, long val) {
+
+ private Map<String, String> mapString = new HashMap<String, String>();
+ private Map<String, MutableLong> mapLong = new HashMap<String, MutableLong>();
+ private Map<String, MutableInt> mapInt = new HashMap<String, MutableInt>();
+ private Map<String, Boolean> mapBoolean = new HashMap<String, Boolean>();
+ private Map<String, MutableFloat> mapFloat = new HashMap<String, MutableFloat>();
+ private Map<String, int[]> mapHist = new HashMap<String, int[]>();
+
+ private static final int MAX_BUCKETS = 60; // Do not expect to see a delay value > 2^59
+
+ public ProfilingData() {}
+
+ public void addString(String key, String val) {
+ mapString.put(key, val);
+ }
+
+ public String getString(String key) {
+ return mapString.get(key);
+ }
+
+ public void addLong(String key, long val) {
mapLong.put(key, new MutableLong(val));
}
+ public void addToHist(String key, long val) {
+ int dat[] = mapHist.get(key);
+ if (dat == null) {
+ dat = new int[MAX_BUCKETS];
+ mapHist.put(key, dat);
+ }
+
+ int bkt = 0;
+ if (val > 1) {
+ val = val >> 1;
+
+ while (val != 0) {
+ bkt++;
+ val = val >> 1;
+ }
+ }
+ dat[bkt]++;
+ }
+
public Long getLong(String key) {
MutableLong ret = mapLong.get(key);
if (ret == null) {
@@ -252,15 +284,15 @@ public class ProfilingData implements Wr
}
}
}
-
- @Override
- public void write(DataOutput out) throws IOException {
- out.writeInt(mapString.size());
- for (Map.Entry<String,String> entry : mapString.entrySet()) {
+
+ @Override
+ public void write(DataOutput out) throws IOException {
+ out.writeInt(mapString.size());
+ for (Map.Entry<String,String> entry : mapString.entrySet()) {
out.writeUTF(entry.getKey());
out.writeUTF(entry.getValue());
}
- out.writeInt(mapBoolean.size());
+ out.writeInt(mapBoolean.size());
for (Map.Entry<String,Boolean> entry : mapBoolean.entrySet()) {
out.writeUTF(entry.getKey());
out.writeBoolean(entry.getValue());
@@ -280,14 +312,20 @@ public class ProfilingData implements Wr
out.writeUTF(entry.getKey());
out.writeFloat(entry.getValue().floatValue());
}
- }
-
- @Override
- public void readFields(DataInput in) throws IOException {
- int size;
- String key;
- size = in.readInt();
- mapString.clear();
+ out.writeInt(mapHist.size());
+ for (Map.Entry<String, int []> entry : mapHist.entrySet()) {
+ out.writeUTF(entry.getKey());
+ int [] values = entry.getValue();
+ writeArray(out, values);
+ }
+ }
+
+ @Override
+ public void readFields(DataInput in) throws IOException {
+ int size;
+ String key;
+ size = in.readInt();
+ mapString.clear();
for (int i = 0; i < size; i ++) {
key = in.readUTF();
this.addString(key, in.readUTF());
@@ -316,10 +354,32 @@ public class ProfilingData implements Wr
key = in.readUTF();
this.addFloat(key, in.readFloat());
}
- }
-
- public String toString(String delim) {
- StringBuilder sb = new StringBuilder ();
+ mapHist.clear();
+ size = in.readInt();
+ for (int i = 0; i < size; i ++) {
+ key = in.readUTF();
+ this.mapHist.put(key, readIntArray(in));
+ }
+ }
+
+ private void writeArray(DataOutput out, int[] values) throws IOException {
+ out.writeInt(values.length);
+ for (int i = 0; i < values.length; i++) {
+ out.writeInt(values[i]);
+ }
+ }
+
+ private int [] readIntArray(DataInput in) throws IOException {
+ int length = in.readInt();
+ int [] values = new int[length];
+ for (int i = 0; i < values.length; i++) {
+ values[i] = in.readInt();
+ }
+ return values;
+ }
+
+ public String toString(String delim) {
+ StringBuilder sb = new StringBuilder ();
for (Map.Entry<String, String> entry : mapString.entrySet()) {
sb.append(entry.getKey() + ":" + entry.getValue() + delim);
}
@@ -335,18 +395,30 @@ public class ProfilingData implements Wr
for (Map.Entry<String, MutableFloat> entry : mapFloat.entrySet()) {
sb.append(entry.getKey() + ":" + entry.getValue() + delim);
}
+ for (Map.Entry<String, int[]> entry : mapHist.entrySet()) {
+ int dat[] = entry.getValue();
+ long max = 2;
+ sb.append(entry.getKey() + ": [" );
+ for (int i = 0; i < dat.length; i++) {
+ if (dat[i] > 0) {
+ sb.append( "<" + max + ":" + dat[i] + delim);
+ }
+ max *= 2;
+ }
+ sb.append( " ]" + delim);
+ }
if (sb.length() >= delim.length()) {
sb.delete(sb.length() - delim.length(), sb.length());
}
return sb.toString();
- }
-
- @Override
- public String toString() {
- return this.toString(", ");
- }
-
- public String toPrettyString() {
- return this.toString("\n");
+ }
+
+ @Override
+ public String toString() {
+ return this.toString(", ");
+ }
+
+ public String toPrettyString() {
+ return this.toString("\n");
}
}
Modified: hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionServer.java
URL: http://svn.apache.org/viewvc/hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionServer.java?rev=1400433&r1=1400432&r2=1400433&view=diff
==============================================================================
--- hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionServer.java (original)
+++ hbase/branches/0.89-fb/src/main/java/org/apache/hadoop/hbase/regionserver/HRegionServer.java Sat Oct 20 12:53:00 2012
@@ -342,6 +342,7 @@ public class HRegionServer implements HR
// throw out an Exception. This is done to avoid OutOfMemory Errors, and
// large GC issues.
private static long responseSizeLimit;
+ public static boolean enableServerSideProfilingForAllCalls;
public static long getResponseSizeLimit() {
return responseSizeLimit;
@@ -400,6 +401,8 @@ public class HRegionServer implements HR
this.responseSizeLimit = conf.getLong("hbase.regionserver.results.size.max",
(long)Integer.MAX_VALUE); // set the max to 2G
+ this.enableServerSideProfilingForAllCalls = conf.getBoolean(
+ "hbase.regionserver.enable.serverside.profiling", false);
reinitialize();
SchemaMetrics.configureGlobally(conf);