You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@hbase.apache.org by "Simon Dircks (Commented) (JIRA)" <ji...@apache.org> on 2012/01/26 00:40:40 UTC
[jira] [Commented] (HBASE-3466) runtime exception -- cached an
already cached block -- during compaction
[ https://issues.apache.org/jira/browse/HBASE-3466?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13193444#comment-13193444 ]
Simon Dircks commented on HBASE-3466:
-------------------------------------
I just reproduced this with hadoop-1.0 and hbase-0.92 with YCSB.
2012-01-25 23:23:51,556 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: regionserver:60020-0x134f70a343101a0 Successfully transitioned node 162702503c650e551130e5fb588b3ec2 from RS_ZK_REGION_SPLIT to RS_ZK_REGION_SPLIT
2012-01-25 23:23:51,616 ERROR org.apache.hadoop.hbase.regionserver.HRegionServer:
java.lang.RuntimeException: Cached an already cached block
at org.apache.hadoop.hbase.io.hfile.LruBlockCache.cacheBlock(LruBlockCache.java:268)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2.readBlock(HFileReaderV2.java:276)
at org.apache.hadoop.hbase.io.hfile.HFileReaderV2$ScannerV2.seekTo(HFileReaderV2.java:487)
at org.apache.hadoop.hbase.io.HalfStoreFileReader$1.seekTo(HalfStoreFileReader.java:168)
at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:181)
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:1721)
at org.apache.hadoop.hbase.regionserver.HRegion$RegionScannerImpl.<init>(HRegion.java:2861)
at org.apache.hadoop.hbase.regionserver.HRegion.instantiateRegionScanner(HRegion.java:1432)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1424)
at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1400)
at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:3688)
at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:3581)
at org.apache.hadoop.hbase.regionserver.HRegionServer.get(HRegionServer.java:1771)
at sun.reflect.GeneratedMethodAccessor38.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:1325)
2012-01-25 23:23:51,656 DEBUG org.apache.hadoop.hbase.zookeeper.ZKAssign: regionserver:60020-0x134f70a343101a0 Attempting to transition node 162702503c650e551130e5fb588b3ec2 from RS_ZK_REGION_SPLIT to RS_ZK_REGION_SPLIT
18 node cluster, dedicated namenode, zookeeper, hbasemaster, and YCSB client machine.
/usr/local/bin/java -cp "build/ycsb.jar:db/hbase/lib/*:db/hbase/conf/" com.yahoo.ycsb.Client -load -db com.yahoo.ycsb.db.HBaseClient -P workloads/workloada -p columnfamily=family1 -p recordcount=5000000 -s > load.dat
loaded 5mil records, that created 8 regions. (balanced all onto the same RS)
/usr/local/bin/java -cp "build/ycsb.jar:db/hbase/lib/*:db/hbase/conf/" com.yahoo.ycsb.Client -t -db com.yahoo.ycsb.db.HBaseClient -P workloads/workloada -p columnfamily=family1 -p operationcount=5000000 -threads 10 -s > transaction.dat
I also was able to reproduce the
2/01/25 15:19:24 WARN client.HConnectionManager$HConnectionImplementation: Failed all from region=usertable,user3076346045817661344,1327530607222.bab55fba6adb17bc8757eb6cdee99a91., hostname=datatask6.hadoop.telescope.tv, port=60020
java.util.concurrent.ExecutionException: java.lang.RuntimeException: java.lang.NullPointerException
found in https://issues.apache.org/jira/browse/HBASE-4890
> runtime exception -- cached an already cached block -- during compaction
> ------------------------------------------------------------------------
>
> Key: HBASE-3466
> URL: https://issues.apache.org/jira/browse/HBASE-3466
> Project: HBase
> Issue Type: Bug
> Affects Versions: 0.90.0
> Environment: ubuntu 9.10, kernel 2.6.31-14-generic SMP 8-core with hyperthreading
> Reporter: M. C. Srivas
> Priority: Critical
>
> Happened while running ycsb against a single RS. BlockSize was set to 64M to tickle more splits. No compression, and replication factor set to 1.
>
> I noticed that https://issues.apache.org/jira/browse/HBASE-2455 applied to 0.20.4, so opened this new one (didn't check to see if the code was the same in 0.20.4 and 0.90.0)
> YCSB was run as follows:
> java -mx3000m -cp conf/:build/ycsb.jar:db/hbase/lib/* com.yahoo.ycsb.Client -t -db com.yahoo.ycsb.db.HBaseClient -P workloads/workloada -p columnfamily=family -p operationcount=10000000 -s -threads 30 -target 30000
> workloada was modified to do 1 billion records:
> ----------
> recordcount=1000000000
> operationcount=1000
> workload=com.yahoo.ycsb.workloads.CoreWorkload
> readallfields=true
> readproportion=0.5
> updateproportion=0.4
> scanproportion=0
> insertproportion=0.1
> requestdistribution=zipfian
> ---------------
> Relevant portions from the RS's log:
> 2011-01-23 10:48:20,719 INFO org.apache.hadoop.hbase.regionserver.SplitTransaction [regionserver60020.compactor]: Starting split of region usertable,,1295808232386.44386ab6079bd5b497a6de3ab95e850c.
> 2011-01-23 10:48:20,788 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Renaming flushed file at maprfs:/hbase/usertable/44386ab6079bd5b497a6de3ab95e850c/.tmp/3202441284831392385 to maprfs:/hbase/usertable/44386ab6079bd5b497a6de3ab95e850c/family/1800354539520698957
> 2011-01-23 10:48:20,791 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Added maprfs:/hbase/usertable/44386ab6079bd5b497a6de3ab95e850c/family/1800354539520698957, entries=10943, sequenceid=128924, memsize=3.4m, filesize=1.5m
> 2011-01-23 10:48:20,792 INFO org.apache.hadoop.hbase.regionserver.HRegion [regionserver60020.compactor]: Closed usertable,,1295808232386.44386ab6079bd5b497a6de3ab95e850c.
> 2011-01-23 10:48:20,828 INFO org.apache.hadoop.hbase.catalog.MetaEditor [regionserver60020.compactor]: Offlined parent region usertable,,1295808232386.44386ab6079bd5b497a6de3ab95e850c. in META
> 2011-01-23 10:48:20,856 INFO org.apache.hadoop.hbase.regionserver.HRegion [perfnode15.perf.lab,60020,1295807975391-daughterOpener=89e0f70da1e5ce2d5c4024ca6cc1addb]: Onlined usertable,,1295808500713.89e0f70da1e5ce2d5c4024ca6cc1addb.; next sequenceid=128925
> 2011-01-23 10:48:20,791 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Added maprfs:/hbase/usertable/44386ab6079bd5b497a6de3ab95e850c/family/1800354539520698957, entries=10943, sequenceid=128924, memsize=3.4m, filesize=1.5m
> 2011-01-23 10:48:20,792 INFO org.apache.hadoop.hbase.regionserver.HRegion [regionserver60020.compactor]: Closed usertable,,1295808232386.44386ab6079bd5b497a6de3ab95e850c.
> 2011-01-23 10:48:20,828 INFO org.apache.hadoop.hbase.catalog.MetaEditor [regionserver60020.compactor]: Offlined parent region usertable,,1295808232386.44386ab6079bd5b497a6de3ab95e850c. in META
> 2011-01-23 10:48:20,856 INFO org.apache.hadoop.hbase.regionserver.HRegion [perfnode15.perf.lab,60020,1295807975391-daughterOpener=89e0f70da1e5ce2d5c4024ca6cc1addb]: Onlined usertable,,1295808500713.89e0f70da1e5ce2d5c4024ca6cc1addb.; next sequenceid=128925
> 2011-01-23 10:48:20,863 INFO org.apache.hadoop.hbase.catalog.MetaEditor [perfnode15.perf.lab,60020,1295807975391-daughterOpener=89e0f70da1e5ce2d5c4024ca6cc1addb]: Added daughter usertable,,1295808500713.89e0f70da1e5ce2d5c4024ca6cc1addb. in region .META.,,1, serverInfo=perfnode15.perf.lab,60020,1295807975391
> 2011-01-23 10:48:20,868 INFO org.apache.hadoop.hbase.regionserver.HRegion [perfnode15.perf.lab,60020,1295807975391-daughterOpener=fd1d4e71c9a7e262a6e26adc0742414e]: Onlined usertable,user1907848630,1295808500713.fd1d4e71c9a7e262a6e26adc0742414e.; next sequenceid=128926
> 2011-01-23 10:48:20,869 INFO org.apache.hadoop.hbase.catalog.MetaEditor [perfnode15.perf.lab,60020,1295807975391-daughterOpener=fd1d4e71c9a7e262a6e26adc0742414e]: Added daughter usertable,user1907848630,1295808500713.fd1d4e71c9a7e262a6e26adc0742414e. in region .META.,,1, serverInfo=perfnode15.perf.lab,60020,1295807975391
> 2011-01-23 10:48:20,870 INFO org.apache.hadoop.hbase.regionserver.CompactSplitThread [regionserver60020.compactor]: Region split, META updated, and report to master. Parent=usertable,,1295808232386.44386ab6079bd5b497a6de3ab95e850c., new regions: usertable,,1295808500713.89e0f70da1e5ce2d5c4024ca6cc1addb., usertable,user1907848630,1295808500713.fd1d4e71c9a7e262a6e26adc0742414e.. Split took 0sec
> 2011-01-23 10:48:20,871 INFO org.apache.hadoop.hbase.regionserver.HRegion [regionserver60020.compactor]: Starting compaction on region usertable,,1295808500713.89e0f70da1e5ce2d5c4024ca6cc1addb.
> 2011-01-23 10:48:20,873 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Started compaction of 4 file(s) in cf=family, hasReferences=true, into maprfs:/hbase/usertable/89e0f70da1e5ce2d5c4024ca6cc1addb/.tmp, seqid=128924, totalSize=271.3m
> 2011-01-23 10:48:21,822 ERROR org.apache.hadoop.hbase.regionserver.HRegionServer [IPC Server handler 1 on 60020]:
> java.lang.RuntimeException: Cached an already cached block
> at org.apache.hadoop.hbase.io.hfile.LruBlockCache.cacheBlock(LruBlockCache.java:252)
> at org.apache.hadoop.hbase.io.hfile.HFile$Reader.readBlock(HFile.java:1056)
> at org.apache.hadoop.hbase.io.hfile.HFile$Reader$Scanner.seekTo(HFile.java:1433)
> at org.apache.hadoop.hbase.io.HalfStoreFileReader$1.seekTo(HalfStoreFileReader.java:160)
> at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seekAtOrAfter(StoreFileScanner.java:139)
> at org.apache.hadoop.hbase.regionserver.StoreFileScanner.seek(StoreFileScanner.java:96)
> at org.apache.hadoop.hbase.regionserver.StoreScanner.<init>(StoreScanner.java:77)
> at org.apache.hadoop.hbase.regionserver.Store.getScanner(Store.java:1338)
> at org.apache.hadoop.hbase.regionserver.HRegion$RegionScanner.<init>(HRegion.java:2229)
> at org.apache.hadoop.hbase.regionserver.HRegion.instantiateInternalScanner(HRegion.java:1119)
> at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1111)
> at org.apache.hadoop.hbase.regionserver.HRegion.getScanner(HRegion.java:1095)
> at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:2951)
> at org.apache.hadoop.hbase.regionserver.HRegion.get(HRegion.java:2853)
> at org.apache.hadoop.hbase.regionserver.HRegionServer.get(HRegionServer.java:1623)
> at sun.reflect.GeneratedMethodAccessor3.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.HBaseRPC$Server.call(HBaseRPC.java:570)
> at org.apache.hadoop.hbase.ipc.HBaseServer$Handler.run(HBaseServer.java:1036)
> 2011-01-23 10:48:28,877 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Completed compaction of 4 file(s), new file=maprfs:/hbase/usertable/89e0f70da1e5ce2d5c4024ca6cc1addb/family/1639385306246002272, size=125.9m; total size for store is 125.9m
> 2011-01-23 10:48:28,877 INFO org.apache.hadoop.hbase.regionserver.HRegion [regionserver60020.compactor]: completed compaction on region usertable,,1295808500713.89e0f70da1e5ce2d5c4024ca6cc1addb. after 8sec
> 2011-01-23 10:48:28,879 INFO org.apache.hadoop.hbase.regionserver.HRegion [regionserver60020.compactor]: Starting compaction on region usertable,user1907848630,1295808500713.fd1d4e71c9a7e262a6e26adc0742414e.
> 2011-01-23 10:48:28,881 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Started compaction of 4 file(s) in cf=family, hasReferences=true, into maprfs:/hbase/usertable/fd1d4e71c9a7e262a6e26adc0742414e/.tmp, seqid=128925, totalSize=271.3m
> 2011-01-23 10:48:33,880 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.compactor]: Completed compaction of 4 file(s), new file=maprfs:/hbase/usertable/fd1d4e71c9a7e262a6e26adc0742414e/family/7964093352375224080, size=141.2m; total size for store is 141.2m
> 2011-01-23 10:48:33,880 INFO org.apache.hadoop.hbase.regionserver.HRegion [regionserver60020.compactor]: completed compaction on region usertable,user1907848630,1295808500713.fd1d4e71c9a7e262a6e26adc0742414e. after 5sec
> 2011-01-23 10:48:44,117 INFO org.apache.hadoop.hbase.regionserver.Store [regionserver60020.cacheFlusher]: Renaming flushed file at maprfs:/hbase/usertable/fd1d4e71c9a7e262a6e26adc0742414e/.tmp/8006640041641015018 to maprfs:/hbase/usertable/fd1d4e
> 71c9a7e262a6e26adc0742414e/family/2931765299907917041
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira