Hi,

We are testing HBase for some read-heavy batch operations, and encountering frequent, silent RegionServer crashes.  The application does many thousands of very selective row scans on a dataset containing several hundred million rows (less than 200GB overall), via thrift.

We have encountered this behavior both on a physical cluster with CDH4 installed, and in an Amazon EMR HBase cluster.  HBase, Thrift, HDFS etc are all running with very minimal customization to the default configurations (in EMR's case, effectively no customization is done at all).

The logs contain some clues, but nothing straightforwardly acknowledging the root cause of failure.  As such it is somewhat scary and we'd really appreciate any advice or suggestions on cause, prevention, etc.
The post-mortem pattern goes like this:
1) RegionServer logs a WARN to the effect of:

 org.apache.hadoop.ipc.HBaseServer
 (responseTooLarge): {"processingtimems":2997,"call":"next(-6754667650407290823, 1000), rpc version=1, client version=29, methodsFingerPrint=1891768260","client":"somehost:55253","starttimems":1359399938999,"queuetimems":0,"class":"HRegionServer","responsesize":231379184,"method":"next"}

2) RegionServer logs one or a few of these at DEBUG, in the second or two before it goes silent:

 org.apache.hadoop.hdfs.DFSClient
 
 Error making BlockReader. Closing stale Socket[addr=/thishost,port=50010,localport=51345]
 java.io.EOFException: Premature EOF: no length prefix available
at org.apache.hadoop.hdfs.protocol.HdfsProtoUtil.vintPrefixed(HdfsProtoUtil.java:162)
at org.apache.hadoop.hdfs.RemoteBlockReader2.newBlockReader(RemoteBlockReader2.java:407)
at org.apache.hadoop.hdfs.BlockReaderFactory.newBlockReader(BlockReaderFactory.java:105)
at org.apache.hadoop.hdfs.DFSInputStream.getBlockReader(DFSInputStream.java:937)
at org.apache.hadoop.hdfs.DFSInputStream.blockSeekTo(DFSInputStream.java:455)
at org.apache.hadoop.hdfs.DFSInputStream.readWithStrategy(DFSInputStream.java:645)
at org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:689)
at java.io.DataInputStream.read(DataInputStream.java:132)
at org.apache.hadoop.hbase.io.hfile.HFileBlock.readWithExtra(HFileBlock.java:454)
at org.apache.hadoop.hbase.io.hfile.HFileBlock$AbstractFSReader.readAtOffset(HFileBlock.java:1062)
at org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderV2.readBlockData(HFileBlock.java:1318)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:266)
at org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.seekToDataBlock(HFileBlockIndex.java:209)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.seekTo(HFileReaderV2.java:519)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.seekTo(HFileReaderV2.java:534)
at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:178)
at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seek(StoreFileScanner.java:111)
at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:83)
at org.apache.hadoop.hbase.regionserver.Store.getScanner(Store.java:1779)
at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.<init>(HRegion.java:2915)
at org.apache.hadoop.hbase.regionserver.HRegion.instantiateRegionScanner(HRegion.java:1453)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1445)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1421)
at org.apache.hadoop.hbase.regionserver.HRegionServer.openScanner(HRegionServer.java:2079)
at sun.reflect.GeneratedMethodAccessor210.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.hadoop.hbase.ipc.WritableRpcEngine$Server.call(WritableRpcEngine.java:364)
at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:1345)
3) HDFS logs this at INFO:

 org.apache.hadoop.hdfs.server.datanode.DataNode
 Exception in receiveBlock for BP-1555962259-thisIP-1358284735183:blk_-5783891561030721738_125644
 java.io.IOException: Premature EOF from inputStream
at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:194)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.doReadFully(PacketReceiver.java:213)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.doRead(PacketReceiver.java:134)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.receiveNextPacket(PacketReceiver.java:109)
at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:414)
at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:635)
at org.apache.hadoop.hdfs.server.datanode.DataXceiver.writeBlock(DataXceiver.java:506)
at org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.opWriteBlock(Receiver.java:98)
at org.apache.hadoop.hdfs.protocol.datatransfer.Receiver.processOp(Receiver.java:66)
at org.apache.hadoop.hdfs.server.datanode.DataXceiver.run(DataXceiver.java:219)
at java.lang.Thread.run(Thread.java:662)

4) HDFS logs this as ERROR:

 org.apache.hadoop.hdfs.server.datanode.DataNode

 thishost:50010:DataXceiver error processing WRITE_BLOCK operation  src: /thishost:50620 dest: /thishost:50010
 java.io.IOException: Premature EOF from inputStream
at org.apache.hadoop.io.IOUtils.readFully(IOUtils.java:194)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.doReadFully(PacketReceiver.java:213)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.doRead(PacketReceiver.java:134)
at org.apache.hadoop.hdfs.protocol.datatransfer.PacketReceiver.receiveNextPacket(PacketReceiver.java:109)
at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receivePacket(BlockReceiver.java:414)
at org.apache.hadoop.hdfs.server.datanode.BlockReceiver.receiveBlock(BlockReceiver.java:635)
at org.apache.hadoop.hdfs.server.datanode.DataXceiver.writeBlock(DataXceiver.java:506

On Mon, Jan 28, 2013 at 12:14 PM, Jim Abramson <[EMAIL PROTECTED]> wrote:

> Hi,
>
> We are testing HBase for some read-heavy batch operations, and
> encountering frequent, silent RegionServer crashes.

'Silent' is interesting.  Which files did you check?  .log and the .out?
 Nothing in the latter?
> The post-mortem pattern goes like this:
>
>
> 1) RegionServer logs a WARN to the effect of:
>
>  org.apache.hadoop.ipc.HBaseServer
>  (responseTooLarge):
> {"processingtimems":2997,"call":"next(-6754667650407290823, 1000), rpc
> version=1, client version=29,
> methodsFingerPrint=1891768260","client":"somehost:55253","starttimems":1359399938999,"queuetimems":0,"class":"HRegionServer","responsesize":231379184,"method":"next"}
>
>

Seems like we are trying to return > 100MB cell.  See around line #386 in
WritableRpcEngine.
Can you figure which region it is when we get this big cell?  We could look
at the hfiles under it using hfile too.  It reports big cells:
http://hbase.apache.org/book.html#hfile_tool2

St.Ack
> 2) RegionServer logs one or a few of these at DEBUG, in the second or two
> before it goes silent:
>
>  org.apache.hadoop.hdfs.DFSClient
>
>  Error making BlockReader. Closing stale
> Socket[addr=/thishost,port=50010,localport=51345]
>  java.io.EOFException: Premature EOF: no length prefix available
>         at
> org.apache.hadoop.hdfs.protocol.HdfsProtoUtil.vintPrefixed(HdfsProtoUtil.java:162)
>
>         at
> org.apache.hadoop.hdfs.RemoteBlockReader2.newBlockReader(RemoteBlockReader2.java:407)
>         at
> org.apache.hadoop.hdfs.BlockReaderFactory.newBlockReader(BlockReaderFactory.java:105)
>         at
> org.apache.hadoop.hdfs.DFSInputStream.getBlockReader(DFSInputStream.java:937)
>         at
> org.apache.hadoop.hdfs.DFSInputStream.blockSeekTo(DFSInputStream.java:455)
>         at
> org.apache.hadoop.hdfs.DFSInputStream.readWithStrategy(DFSInputStream.java:645)
>         at
> org.apache.hadoop.hdfs.DFSInputStream.read(DFSInputStream.java:689)
>         at java.io.DataInputStream.read(DataInputStream.java:132)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileBlock.readWithExtra(HFileBlock.java:454)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileBlock$AbstractFSReader.readAtOffset(HFileBlock.java:1062)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileBlock$FSReaderV2.readBlockData(HFileBlock.java:1318)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:266)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$BlockIndexReader.seekToDataBlock(HFileBlockIndex.java:209)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.seekTo(HFileReaderV2.java:519)
>         at
> org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.seekTo(HFileReaderV2.java:534)
>         at
> org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:178)
>         at
> org.apache.hadoop.hbase.regionserver.StoreFileScanner.seek(StoreFileScanner.java:111)
>         at
> org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:83)
>         at
> org.apache.hadoop.hbase.regionserver.Store.getScanner(Store.java:1779)
>         at
> org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.<init>(HRegion.java:2915)
>         at
> org.apache.hadoop.hbase.regionserver.HRegion.instantiateRegionScanner(HRegion.java:1453)
>         at
> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1445)
>         at
> org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1421)
>         at
> org.apache.hadoop.hbase.regionserver.HRegionServer.openScanner(HRegionServer.java:2079)
>         at sun.reflect.GeneratedMethodAccessor210.invoke(Unknown Source)
>         at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
>         at java.lang.reflect.Method.invoke(Method.java:597)
>         at
> org.apache.hadoop.hbase.ipc.WritableRpcEngine$Server.call(WritableRpcEngine.java:364)

On Mon, Jan 28, 2013 at 12:14 PM, Jim Abramson <[EMAIL PROTECTED]<mailto:[EMAIL PROTECTED]>> wrote:

> Hi,
>
> We are testing HBase for some read-heavy batch operations, and
> encountering frequent, silent RegionServer crashes.

'Silent' is interesting.  Which files did you check?  .log and the .out?
 Nothing in the latter?

Thanks very much for your reply.

In fact, .out log did indicate OOMEs here.  I looked right past this initially, as their formatting makes the "kill -9 N" output look like ignorable comments to a Python developer :-)

Knowing that this was the problem all along, I've been doing some experimenting and trying to figure out how to prevent this from happening.

My use case calls for lots of long RowKey scans arriving in bursts, alongside a steady stream of puts and random-access reads.  Based on what I've read here http://hbase.apache.org/book/regionserver.arch.html, I assumed that disabling caching on my scans would help.  And to an extent it did, as the RegionServers' heap usage stays much more level now while I'm scanning.  Unfortunately, now my thrift servers are going OOM during the scans, in exactly the same way - which is arguably better, but still far from acceptable for production.

Any advice on how to harden the system overall against these kinds of memory issues?  I'm disinclined to simply jack up memory allocations and hope for the best, since that seems like postponement of the problem, not prevention.

As far as thrift is concerned, i did notice HBASE-4863 and it seems promising, but I may be locked into 0.92 initially.

Jim