Return-Path: X-Original-To: apmail-hbase-issues-archive@www.apache.org Delivered-To: apmail-hbase-issues-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 97778913B for ; Thu, 26 Jan 2012 00:46:03 +0000 (UTC) Received: (qmail 98393 invoked by uid 500); 26 Jan 2012 00:46:03 -0000 Delivered-To: apmail-hbase-issues-archive@hbase.apache.org Received: (qmail 98233 invoked by uid 500); 26 Jan 2012 00:46:02 -0000 Mailing-List: contact issues-help@hbase.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list issues@hbase.apache.org Received: (qmail 97876 invoked by uid 99); 26 Jan 2012 00:46:02 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 26 Jan 2012 00:46:02 +0000 X-ASF-Spam-Status: No, hits=-2000.0 required=5.0 tests=ALL_TRUSTED,T_RP_MATCHES_RCVD X-Spam-Check-By: apache.org Received: from [140.211.11.116] (HELO hel.zones.apache.org) (140.211.11.116) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 26 Jan 2012 00:46:00 +0000 Received: from hel.zones.apache.org (hel.zones.apache.org [140.211.11.116]) by hel.zones.apache.org (Postfix) with ESMTP id AF5D5163B39 for ; Thu, 26 Jan 2012 00:45:40 +0000 (UTC) Date: Thu, 26 Jan 2012 00:45:40 +0000 (UTC) From: "Zhihong Yu (Commented) (JIRA)" To: issues@hbase.apache.org Message-ID: <1367882951.79000.1327538740719.JavaMail.tomcat@hel.zones.apache.org> In-Reply-To: <7458856.139761295817764531.JavaMail.jira@thor> Subject: [jira] [Commented] (HBASE-3466) runtime exception -- cached an already cached block -- during compaction MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HBASE-3466?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13193483#comment-13193483 ] Zhihong Yu commented on HBASE-3466: ----------------------------------- @Simon: Thanks for sharing this information. This JIRA has been closed. Do you mind creating a new JIRA ? > 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.(StoreScanner.java:77) > at org.apache.hadoop.hbase.regionserver.Store.getScanner(Store.java:1338) > at org.apache.hadoop.hbase.regionserver.HRegion$RegionScanner.(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