[HBASE-15392] Single Cell Get reads two HFileBlocks - ASF JIRA

Details

Type: Sub-task
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.3.0, 2.0.0
Component/s: BucketCache
Labels:
None

Hadoop Flags:

Reviewed
Release Note:

Hide
When an explicit Get with a one or more columns specified, we at a minimum, were overseeking, reading until we tripped over the next row, regardless, and only then returning. If the next row was in-block, we'd just do too much seeking but if the next row was in the next (or in the next block beyond that), we would keep seeking and loading blocks until we found the next row before we'd return.

There remains one case where we will still 'overread'. It is when the row end aligns with the end of the block. In this case we will load the next block just to find that there are no more cells in the current row. See HBASE-15457.

Show
When an explicit Get with a one or more columns specified, we at a minimum, were overseeking, reading until we tripped over the next row, regardless, and only then returning. If the next row was in-block, we'd just do too much seeking but if the next row was in the next (or in the next block beyond that), we would keep seeking and loading blocks until we found the next row before we'd return. There remains one case where we will still 'overread'. It is when the row end aligns with the end of the block. In this case we will load the next block just to find that there are no more cells in the current row. See HBASE-15457 .

Description

As found by Daniel "SystemTap" Pol, a simple Get results in our reading two HFileBlocks, the one that contains the wanted Cell, and the block that follows.

Here is a bit of custom logging that logs a stack trace on each HFileBlock read so you can see the call stack responsible:

2016-03-03 22:20:30,191 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] regionserver.StoreScanner: START LOOP
2016-03-03 22:20:30,192 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] regionserver.StoreScanner: QCODE SEEK_NEXT_COL
2016-03-03 22:20:30,192 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileBlockIndex: STARTED WHILE
2016-03-03 22:20:30,192 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.CombinedBlockCache: OUT OF L2
2016-03-03 22:20:30,192 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] bucket.BucketCache: Read offset=31409152, len=2103
2016-03-03 22:20:30,192 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] bucket.FileIOEngine: offset=31409152, length=2103
2016-03-03 22:20:30,193 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileReaderImpl: From Cache [blockType=DATA, fileOffset=2055421, headerSize=33, onDiskSizeWithoutHeader=2024, uncompressedSizeWithoutHeader=2020, prevBlockOffset=2053364, isUseHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, onDiskDataSizeWithHeader=2053, getOnDiskSizeWithHeader=2057, totalChecksumBytes=4, isUnpacked=true, buf=[org.apache.hadoop.hbase.nio.SingleByteBuff@e19fbd54], dataBeginsWith=\x00\x00\x00)\x00\x00\x01`\x00\x16user995139035672819231, fileContext=[usesHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, blocksize=65536, encoding=NONE, includesMvcc=true, includesTags=false, compressAlgo=NONE, compressTags=false, cryptoContext=[cipher=NONE keyHash=NONE]]]
2016-03-03 22:20:30,193 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileReaderImpl: Cache hit return [blockType=DATA, fileOffset=2055421, headerSize=33, onDiskSizeWithoutHeader=2024, uncompressedSizeWithoutHeader=2020, prevBlockOffset=2053364, isUseHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, onDiskDataSizeWithHeader=2053, getOnDiskSizeWithHeader=2057, totalChecksumBytes=4, isUnpacked=true, buf=[org.apache.hadoop.hbase.nio.SingleByteBuff@e19fbd54], dataBeginsWith=\x00\x00\x00)\x00\x00\x01`\x00\x16user995139035672819231, fileContext=[usesHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, blocksize=65536, encoding=NONE, includesMvcc=true, includesTags=false, compressAlgo=NONE, compressTags=false, cryptoContext=[cipher=NONE keyHash=NONE]]]
java.lang.Throwable
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl.readBlock(HFileReaderImpl.java:1515)
        at org.apache.hadoop.hbase.io.hfile.HFileBlockIndex$CellBasedKeyBlockIndexReader.loadDataBlockWithScanInfo(HFileBlockIndex.java:324)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl.seekTo(HFileReaderImpl.java:831)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl.reseekTo(HFileReaderImpl.java:812)
        at org.apache.hadoop.hbase.regionserver.StoreFileScanner.reseekAtOrAfter(StoreFileScanner.java:288)
        at org.apache.hadoop.hbase.regionserver.StoreFileScanner.reseek(StoreFileScanner.java:198)
        at org.apache.hadoop.hbase.regionserver.NonLazyKeyValueScanner.doRealSeek(NonLazyKeyValueScanner.java:54)
        at org.apache.hadoop.hbase.regionserver.KeyValueHeap.generalizedSeek(KeyValueHeap.java:321)
        at org.apache.hadoop.hbase.regionserver.KeyValueHeap.requestSeek(KeyValueHeap.java:279)
        at org.apache.hadoop.hbase.regionserver.StoreScanner.reseek(StoreScanner.java:806)
        at org.apache.hadoop.hbase.regionserver.StoreScanner.seekAsDirection(StoreScanner.java:795)
        at org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:624)
        at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:153)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.populateResult(HRegion.java:5703)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextInternal(HRegion.java:5849)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextRaw(HRegion.java:5622)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.next(HRegion.java:5598)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.next(HRegion.java:5584)
        at org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2187)
        at org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2123)
        at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:33512)
        at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2229)
        at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:109)
        at org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.java:136)
        at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:111)
        at java.lang.Thread.run(Thread.java:745)
2016-03-03 22:20:30,193 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileBlockIndex: READ [blockType=DATA, fileOffset=2055421, headerSize=33, onDiskSizeWithoutHeader=2024, uncompressedSizeWithoutHeader=2020, prevBlockOffset=2053364, isUseHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, onDiskDataSizeWithHeader=2053, getOnDiskSizeWithHeader=2057, totalChecksumBytes=4, isUnpacked=true, buf=[org.apache.hadoop.hbase.nio.SingleByteBuff@e19fbd54], dataBeginsWith=\x00\x00\x00)\x00\x00\x01`\x00\x16user995139035672819231, fileContext=[usesHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, blocksize=65536, encoding=NONE, includesMvcc=true, includesTags=false, compressAlgo=NONE, compressTags=false, cryptoContext=[cipher=NONE keyHash=NONE]]]
2016-03-03 22:20:30,193 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileBlockIndex: DATA BLOCK IS TRUE BREAK
2016-03-03 22:20:30,193 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileBlockIndex: RETURNING
2016-03-03 22:20:30,194 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] regionserver.StoreScanner: QCODE INCLUDE
2016-03-03 22:20:30,194 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] regionserver.StoreScanner: QCODE SKIP
2016-03-03 22:20:30,194 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.CombinedBlockCache: OUT OF L2
2016-03-03 22:20:30,194 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] bucket.BucketCache: Read offset=30932992, len=2103
2016-03-03 22:20:30,194 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] bucket.FileIOEngine: offset=30932992, length=2103
2016-03-03 22:20:30,194 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileReaderImpl: From Cache [blockType=DATA, fileOffset=2057478, headerSize=33, onDiskSizeWithoutHeader=2024, uncompressedSizeWithoutHeader=2020, prevBlockOffset=2055421, isUseHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, onDiskDataSizeWithHeader=2053, getOnDiskSizeWithHeader=2057, totalChecksumBytes=4, isUnpacked=true, buf=[org.apache.hadoop.hbase.nio.SingleByteBuff@6063ac95], dataBeginsWith=\x00\x00\x00)\x00\x00\x01`\x00\x16user995698996184959679, fileContext=[usesHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, blocksize=65536, encoding=NONE, includesMvcc=true, includesTags=false, compressAlgo=NONE, compressTags=false, cryptoContext=[cipher=NONE keyHash=NONE]]]
2016-03-03 22:20:30,194 TRACE [B.defaultRpcServer.handler=20,queue=2,port=16020] hfile.HFileReaderImpl: Cache hit return [blockType=DATA, fileOffset=2057478, headerSize=33, onDiskSizeWithoutHeader=2024, uncompressedSizeWithoutHeader=2020, prevBlockOffset=2055421, isUseHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, onDiskDataSizeWithHeader=2053, getOnDiskSizeWithHeader=2057, totalChecksumBytes=4, isUnpacked=true, buf=[org.apache.hadoop.hbase.nio.SingleByteBuff@6063ac95], dataBeginsWith=\x00\x00\x00)\x00\x00\x01`\x00\x16user995698996184959679, fileContext=[usesHBaseChecksum=true, checksumType=CRC32C, bytesPerChecksum=16384, blocksize=65536, encoding=NONE, includesMvcc=true, includesTags=false, compressAlgo=NONE, compressTags=false, cryptoContext=[cipher=NONE keyHash=NONE]]]
java.lang.Throwable
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl.readBlock(HFileReaderImpl.java:1515)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl.readNextDataBlock(HFileReaderImpl.java:906)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl.isNextBlock(HFileReaderImpl.java:1106)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl.positionForNextBlock(HFileReaderImpl.java:1100)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl._next(HFileReaderImpl.java:1118)
        at org.apache.hadoop.hbase.io.hfile.HFileReaderImpl$HFileScannerImpl.next(HFileReaderImpl.java:1139)
        at org.apache.hadoop.hbase.regionserver.StoreFileScanner.next(StoreFileScanner.java:152)
        at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:114)
        at org.apache.hadoop.hbase.regionserver.StoreScanner.next(StoreScanner.java:628)
        at org.apache.hadoop.hbase.regionserver.KeyValueHeap.next(KeyValueHeap.java:153)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.populateResult(HRegion.java:5703)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextInternal(HRegion.java:5849)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.nextRaw(HRegion.java:5622)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.next(HRegion.java:5598)
        at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.next(HRegion.java:5584)
        at org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2187)
        at org.apache.hadoop.hbase.regionserver.RSRpcServices.get(RSRpcServices.java:2123)
        at org.apache.hadoop.hbase.protobuf.generated.ClientProtos$ClientService$2.callBlockingMethod(ClientProtos.java:33512)
        at org.apache.hadoop.hbase.ipc.RpcServer.call(RpcServer.java:2229)
        at org.apache.hadoop.hbase.ipc.CallRunner.run(CallRunner.java:109)
        at org.apache.hadoop.hbase.ipc.RpcExecutor.consumerLoop(RpcExecutor.java:136)
        at org.apache.hadoop.hbase.ipc.RpcExecutor$1.run(RpcExecutor.java:111)
        at java.lang.Thread.run(Thread.java:745)
2016-03-03 22:20:30,195 INFO  [B.defaultRpcServer.handler=20,queue=2,port=16020] regionserver.StoreScanner: QCODE DONE

We are in StoreScanner#next.

Matcher does SEEK_NEXT_COL.
We pull in the block that has our Cell in it.
Matcher does INCLUDE
Then Matcher does SKIP
SKIP has us go read the next block.
Then Matcher does DONE.

Why ain't I getting to DONE after INCLUDE?

Any clues?

This code has been like this a while.

Attachments

- Sort By Name
- Sort By Date
- Ascending
- Descending

15392.wip.patch
05/Mar/16 00:33
17 kB
Michael Stack
15392v2.wip.patch
05/Mar/16 06:15
7 kB
Michael Stack
two_seeks.txt
05/Mar/16 21:09
20 kB
Michael Stack
no_optimize.patch
05/Mar/16 23:37
15 kB
Michael Stack
no_optimize.patch
05/Mar/16 23:37
15 kB
Michael Stack
15392v3.wip.patch
05/Mar/16 23:47
8 kB
Michael Stack
15392-0.98-looksee.txt
06/Mar/16 21:11
1 kB
Lars Hofhansl
HBASE-15392_suggest.patch
07/Mar/16 05:21
3 kB
ramkrishna.s.vasudevan
15392v4.patch
08/Mar/16 20:15
22 kB
Michael Stack
gc.png
10/Mar/16 05:51
30 kB
Michael Stack
reads.png
10/Mar/16 05:51
15 kB
Michael Stack
io.png
10/Mar/16 05:56
15 kB
Michael Stack
gc.png
10/Mar/16 05:56
30 kB
Michael Stack
reads.png
10/Mar/16 05:56
15 kB
Michael Stack
15392v5.patch
11/Mar/16 08:08
29 kB
Michael Stack
15392v6.patch
12/Mar/16 22:35
36 kB
Michael Stack
15392v7.patch
13/Mar/16 00:14
36 kB
Michael Stack
15392v7.patch
14/Mar/16 15:24
36 kB
Michael Stack
15392v7.patch
14/Mar/16 16:43
36 kB
Michael Stack
15392v7.patch
14/Mar/16 18:03
36 kB
Michael Stack
15392v7.patch
15/Mar/16 12:53
36 kB
Michael Stack
15392v7 (1).patch
18/Mar/16 23:35
36 kB
Michael Stack
HBASE-15265-v8.patch
22/Mar/16 05:26
311 kB
Michael Stack
15392v9.patch
23/Mar/16 21:39
37 kB
Michael Stack
15392.backport.branch-1.patch
22/Apr/16 05:41
23 kB
Michael Stack

Single Cell Get reads two HFileBlocks

Details

Description

Attachments

Attachments

Activity

People

Dates