[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-tabpanelfocusedCommentId=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=500 -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=500 -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=1000 -s -threads 30 -target 3 workloada was modified to do 1 billion records: -- recordcount=10 operationcount=1000
[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-tabpanelfocusedCommentId=13193491#comment-13193491
]
Zhihong Yu commented on HBASE-3466:
---
Since the issue can be reproduced, can you include cacheKey (and cb) in the
exception message ?
{code}
CachedBlock cb = map.get(cacheKey);
if(cb != null) {
throw new RuntimeException(Cached an already cached block);
}
{code}
Thanks
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=1000 -s -threads 30 -target 3
workloada was modified to do 1 billion records:
--
recordcount=10
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
[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-tabpanelfocusedCommentId=12990815#comment-12990815 ] Jonathan Gray commented on HBASE-3466: -- Have never seen this and have done extensive testing on 90 and the block cache. 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=1000 -s -threads 30 -target 3 workloada was modified to do 1 billion records: -- recordcount=10 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,
[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-tabpanelfocusedCommentId=12990823#comment-12990823 ] Ted Dunning commented on HBASE-3466: We haven't seen this since this one occurrence. 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=1000 -s -threads 30 -target 3 workloada was modified to do 1 billion records: -- recordcount=10 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
