Return-Path: X-Original-To: apmail-cassandra-user-archive@www.apache.org Delivered-To: apmail-cassandra-user-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 762FFD7D1 for ; Thu, 28 Feb 2013 20:20:13 +0000 (UTC) Received: (qmail 51915 invoked by uid 500); 28 Feb 2013 20:20:10 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 51846 invoked by uid 500); 28 Feb 2013 20:20:10 -0000 Mailing-List: contact user-help@cassandra.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: user@cassandra.apache.org Delivered-To: mailing list user@cassandra.apache.org Received: (qmail 51836 invoked by uid 99); 28 Feb 2013 20:20:10 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 28 Feb 2013 20:20:10 +0000 X-ASF-Spam-Status: No, hits=0.9 required=5.0 tests=HTML_MESSAGE,RCVD_IN_DNSWL_MED,SPF_SOFTFAIL,UNPARSEABLE_RELAY X-Spam-Check-By: apache.org Received-SPF: softfail (athena.apache.org: transitioning domain of andras.szerdahelyi@ignitionone.com does not designate 216.82.243.50 as permitted sender) Received: from [216.82.243.50] (HELO mail1.bemta8.messagelabs.com) (216.82.243.50) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 28 Feb 2013 20:20:05 +0000 Received: from [216.82.241.132:33433] by server-12.bemta-8.messagelabs.com id A5/44-01647-0EBBF215; Thu, 28 Feb 2013 20:19:44 +0000 X-Env-Sender: andras.szerdahelyi@ignitionone.com X-Msg-Ref: server-6.tower-45.messagelabs.com!1362082783!10967402!1 X-Originating-IP: [208.52.173.250] X-StarScan-Received: X-StarScan-Version: 6.8.6; banners=-,-,- X-VirusChecked: Checked Received: (qmail 21224 invoked from network); 28 Feb 2013 20:19:43 -0000 Received: from mail.dentsunetwork.com (HELO mail.dentsunetwork.com) (208.52.173.250) by server-6.tower-45.messagelabs.com with AES128-SHA encrypted SMTP; 28 Feb 2013 20:19:43 -0000 Received: from ATL02MB02.corp.local ([fe80::7997:c980:b031:df37]) by ATL02HUB02.corp.local ([::1]) with mapi id 14.02.0318.004; Thu, 28 Feb 2013 15:19:44 -0500 From: Andras Szerdahelyi To: "user@cassandra.apache.org" Subject: Re: "Heap is N.N full." Immediately on startup Thread-Topic: "Heap is N.N full." Immediately on startup Thread-Index: AQHOEFTN5vgjl2oKVkaN8J6uruEhPZiFGZ+AgAFRUACABgAxgIADjySAgAAriwA= Date: Thu, 28 Feb 2013 20:19:42 +0000 Message-ID: In-Reply-To: <2469E318-3368-49D8-9897-9907BF99C2DF@thelastpickle.com> Accept-Language: en-US Content-Language: en-US X-MS-Has-Attach: X-MS-TNEF-Correlator: user-agent: Microsoft-MacOutlook/14.3.1.130117 x-originating-ip: [10.0.90.2] Content-Type: multipart/alternative; boundary="_000_FE84AE7AAE9A2B4EA73512EED142BEF830CA4D0EATL02MB02corplo_" MIME-Version: 1.0 X-Virus-Checked: Checked by ClamAV on apache.org --_000_FE84AE7AAE9A2B4EA73512EED142BEF830CA4D0EATL02MB02corplo_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable INFO [ScheduledTasks:1] 2013-02-28 14:48:59,335 GCInspector.java (line 122)= GC for ConcurrentMarkSweep: 1315 ms for 1 collections, 6558662864 used; ma= x is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:49:22,530 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 661 ms for 1 collections, 7302433920 used; ma= x is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:49:43,595 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 820 ms for 1 collections, 7494556024 used; ma= x is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:50:06,002 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 1057 ms for 1 collections, 7867906264 used; m= ax is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:50:26,432 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 1025 ms for 1 collections, 7845991024 used; m= ax is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:50:50,266 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 624 ms for 1 collections, 7148089096 used; ma= x is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:51:12,549 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 617 ms for 1 collections, 7092289680 used; ma= x is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:51:34,433 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 821 ms for 1 collections, 7454785104 used; ma= x is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:51:58,054 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 1326 ms for 1 collections, 7767441672 used; m= ax is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:52:22,980 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 1103 ms for 1 collections, 7649036600 used; m= ax is 8422162432 INFO [ScheduledTasks:1] 2013-02-28 14:52:42,887 GCInspector.java (line 122= ) GC for ConcurrentMarkSweep: 877 ms for 1 collections, 7317935816 used; ma= x is 8422162432 Does not take too long, but maybe it happens a bit too often ? I'll experim= ent with reducing the bloom filter and/or increasing the heap ( maybe the n= ewgen a bit ) Thanks for the tips! Andras From: aaron morton = > Reply-To: "user@cassandra.apache.org" > Date: Thursday 28 February 2013 19:43 To: "user@cassandra.apache.org" > Subject: Re: "Heap is N.N full." Immediately on startup - still getting 1-2 sstable reads with LCS That's bang in the wheel house http://www.datastax.com/dev/blog/when-to-use-leveled-compaction However at startup I see a 5GB old gen ( that seems to be very stable at ar= ound 5.5GB under moderate 90:10 read:write load - couple hundred q/s ) At 300 to 400 million rows that sounds roughly right. I've not done any cal= culations, but I just spilt a coffee and checked the stain it made. The interesting thing is what happens at the end of a CMS run. How low does= it get ? Also hinted handoff is off, as full GC pauses of 1-3seconds on nodes I hav= e not yet attended to I would look at the first. Search the user group for "correlate compaction gc" as a starting point. Cheers ----------------- Aaron Morton Freelance Cassandra Developer New Zealand @aaronmorton http://www.thelastpickle.com ----------------- Aaron Morton Freelance Cassandra Developer New Zealand @aaronmorton http://www.thelastpickle.com On 26/02/2013, at 3:22 AM, Andras Szerdahelyi > wrote: ( I am monitoring via a visual vm plugin that shows generation sizes ) I've increased the index sampling rate from 64 to 512 and the bloom filter = fp ratio from default to 0.1 ( and rebuilt stables ) - still getting 1-2 ss= table reads with LCS However at startup I see a 5GB old gen ( that seems to be very stable at ar= ound 5.5GB under moderate 90:10 read:write load - couple hundred q/s ) is t= hat a realistic size with these values and a ~200GB CF with 3-400mil rows? = ( no secondary indexes, skinny rows 1-5K each ) ? Also hinted handoff is off, as full GC pauses of 1-3seconds on nodes I have= not yet attended to ( sampling rate at 64, bloom fp default ) are kicking = off the failure detector even at a phi_convict_threshold of 12 ( apparently= ? ) and everything is in an up/down dance :-) Thanks! Andras From: aaron morton = > Reply-To: "user@cassandra.apache.org" > Date: Friday 22 February 2013 17:44 To: "user@cassandra.apache.org" > Subject: Re: "Heap is N.N full." Immediately on startup To get a good idea of how GC is performing turn on the GC logging in cassan= dra-env.sh. After a full cms GC event, see how big the tenured heap is. If it's not red= ucing enough then GC will never get far enough ahead. Cheers ----------------- Aaron Morton Freelance Cassandra Developer New Zealand @aaronmorton http://www.thelastpickle.com On 22/02/2013, at 8:37 AM, Andras Szerdahelyi > wrote: Thank you- indeed my index interval is 64 with a CF of 300M rows + bloom fi= lter false positive chance was default. Raising the index interval to 512 didn't fix this alone, so I guess I'll h= ave to set the bloom filter to some reasonable value and scrub. From: aaron morton = > Reply-To: "user@cassandra.apache.org" > Date: Thursday 21 February 2013 17:58 To: "user@cassandra.apache.org" > Subject: Re: "Heap is N.N full." Immediately on startup My first guess would be the bloom filter and index sampling from lots-o-row= s Check the row count in cfstats Check the bloom filter size in cfstats. Background on memory requirements http://www.mail-archive.com/user@cassandr= a.apache.org/msg25762.html Cheers ----------------- Aaron Morton Freelance Cassandra Developer New Zealand @aaronmorton http://www.thelastpickle.com On 20/02/2013, at 11:27 PM, Andras Szerdahelyi > wrote: Hey list, Any ideas ( before I take a heap dump ) what might be consuming my 8GB JVM = heap at startup in Cassandra 1.1.6 besides * row cache : not persisted and is at 0 keys when this warning is produ= ced * Memtables : no write traffic at startup, my app's column families are= durable_writes:false * Pending tasks : no pending tasks, except for 928 compactions ( not su= re where those are coming from ) I drew these conclusions from the StatusLogger output below: INFO [ScheduledTasks:1] 2013-02-20 05:13:25,198 GCInspector.java (line 122)= GC for ConcurrentMarkSweep: 14959 ms for 2 collections, 7017934560 used; m= ax is 8375238656 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,198 StatusLogger.java (line 57= ) Pool Name Active Pending Blocked INFO [ScheduledTasks:1] 2013-02-20 05:13:25,199 StatusLogger.java (line 72= ) ReadStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,200 StatusLogger.java (line 72= ) RequestResponseStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,200 StatusLogger.java (line 72= ) ReadRepairStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,200 StatusLogger.java (line 72= ) MutationStage 0 -1 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.java (line 72= ) ReplicateOnWriteStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.java (line 72= ) GossipStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.java (line 72= ) AntiEntropyStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.java (line 72= ) MigrationStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.java (line 72= ) StreamStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.java (line 72= ) MemtablePostFlusher 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.java (line 72= ) FlushWriter 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.java (line 72= ) MiscStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.java (line 72= ) commitlog_archiver 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,203 StatusLogger.java (line 72= ) InternalResponseStage 0 0 0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.java (line 77= ) CompactionManager 0 928 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.java (line 89= ) MessagingService n/a 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.java (line 99= ) Cache Type Size Capacity = KeysToSave Provid= er INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.java (line 10= 0) KeyCache 25 25 = all INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 10= 6) RowCache 0 0 = all org.apache.cassandra.cache.SerializingCacheProvi= der INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 3) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 6) MYAPP_1.CF 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 6) MYAPP_2.CF 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 6) HiveMetaStore.MetaStore 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 6) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 6) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.java (line 11= 6) system.LocationInfo 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.Versions 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.Migrations 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.schema_columns 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.HintsColumnFamily 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) system.Schema 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) cfs_archive.sblocks 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.java (line 11= 6) cfs_archive.cleanup 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) cfs_archive.inode 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) cfs.cleanup 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) cfs.sblocks 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) cfs.inode 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) OpsCenter.events 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) OpsCenter.rollups300 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) OpsCenter.rollups86400 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) OpsCenter.pdps 345,54448 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.java (line 11= 6) OpsCenter.events_timeline 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.java (line 11= 6) OpsCenter.settings 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.java (line 11= 6) OpsCenter.rollups7200 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.java (line 11= 6) OpsCenter.rollups60 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.java (line 11= 6) demo.users 0,0 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.java (line 11= 6) MYAPP_3.CF 0,0 WARN [ScheduledTasks:1] 2013-02-20 05:13:25,216 GCInspector.java (line 145= ) Heap is 0.8379384574280004 full. You may need to reduce memtable and/or = cache sizes. Cassandra will now flush up to the two largest memtables to f= ree up memory. Adjust flush_largest_memtables_at threshold in cassandra.ya= ml if you don't want Cassandra to do this automatically WARN [ScheduledTasks:1] 2013-02-20 05:13:25,217 StorageService.java (line = 2855) Flushing CFS(Keyspace=3D'OpsCenter', ColumnFamily=3D'pdps') to reliev= e memory pressure INFO [ScheduledTasks:1] 2013-02-20 05:13:25,217 ColumnFamilyStore.java (li= ne 659) Enqueuing flush of Memtable-pdps@98567689(15238/54448 serialized/li= ve bytes, 345 ops) INFO [FlushWriter:6] 2013-02-20 05:13:25,218 Memtable.java (line 264) Writ= ing Memtable-pdps@98567689(15238/54448 serialized/live bytes, 345 ops) INFO [FlushWriter:6] 2013-02-20 05:13:25,241 Memtable.java (line 305) Comp= leted flushing /var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hf-127= -Data.db (5394 bytes) for commitlog position ReplayPosition(segmentId=3D136= 1354508149, : Thanks! Andras --_000_FE84AE7AAE9A2B4EA73512EED142BEF830CA4D0EATL02MB02corplo_ Content-Type: text/html; charset="us-ascii" Content-ID: Content-Transfer-Encoding: quoted-printable
INFO [ScheduledTasks:1] 2013-02-28 14:48:59,335 GCInspector.java (line= 122) GC for ConcurrentMarkSweep: 1315 ms for 1 collections, 6558662864 use= d; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:49:22,530 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 661 ms for 1 collections, 730243392= 0 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:49:43,595 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 820 ms for 1 collections, 749455602= 4 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:50:06,002 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 1057 ms for 1 collections, 78679062= 64 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:50:26,432 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 1025 ms for 1 collections, 78459910= 24 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:50:50,266 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 624 ms for 1 collections, 714808909= 6 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:51:12,549 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 617 ms for 1 collections, 709228968= 0 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:51:34,433 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 821 ms for 1 collections, 745478510= 4 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:51:58,054 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 1326 ms for 1 collections, 77674416= 72 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:52:22,980 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 1103 ms for 1 collections, 76490366= 00 used; max is 8422162432
 INFO [ScheduledTasks:1] 2013-02-28 14:52:42,887 GCInspector.java= (line 122) GC for ConcurrentMarkSweep: 877 ms for 1 collections, 731793581= 6 used; max is 8422162432

Does not take too long, but maybe it happens a bit too often ? I'll ex= periment with reducing the bloom filter and/or increasing the heap ( maybe = the newgen a bit )

Thanks for the tips!
Andras

From: aaron morton <aaron@thelastpickle.com>
Reply-To: "user@cassandra.apache.org" <user@cassandra.apache.org>
Date: Thursday 28 February 2013 19:= 43
To: "user@cassandra.apache.org" <user@cassandra.apache.org>
Subject: Re: "Heap is N.N full= ." Immediately on startup

- still getting 1-2 sstable reads with LCS
That's bang in the wheel house
http://www.datastax.com/dev/blog/when-to-use-leveled-compaction

However at startup I see a 5GB old gen ( that seems to be very stable at ar= ound 5.5GB under moderate 90:10 read:write load - couple hundred q/s ) = ;
At 300 to 400 million rows that sounds roughly right. I've not done any cal= culations, but I just spilt a coffee and checked the stain it made. 

The interesting thing is what happens at the end of a CMS run. How low= does it get ?

 Also hinted handoff is off, as full GC pauses of 1= -3seconds on nodes I have not yet attended to
I would look at the first. 
Search the user group for "correlate compaction gc" as a sta= rting point. 

Cheers

-----------------
Aaron Morton
Freelance Cassandra Developer
New Zealand

@aaronmorton

( I am monitoring via a visual vm plugin that shows generation sizes )=
I've increased the index sampling rate from 64 to 512 and the bloom fi= lter fp ratio from default to 0.1 ( and rebuilt stables ) - still getting 1= -2 sstable reads with LCS
However at startup I see a 5GB old gen ( that seems to be very stable = at around 5.5GB under moderate 90:10 read:write load - couple hundred q/s )= is that a realistic size with these values and a ~200GB CF with 3-400mil r= ows? ( no secondary indexes, skinny rows 1-5K each ) ? 

Also hinted handoff is off, as full GC pauses of 1-3seconds on nodes I= have not yet attended to ( sampling rate at 64, bloom fp default ) are kic= king off the failure detector even at a phi_convict_threshold of 12 ( = apparently ? ) and everything is in an up/down dance :-)

Thanks!
Andras

From: aaron morton <aaron@thelastpickle.com>
Reply-To: "user@cassandra.apache.org" <user@cassandra.apache.org>
Date: Friday 22 February 2013 17:44=
To: "user@cassandra.apache.org" <user@cassandra.apache.org>
Subject: Re: "Heap is N.N full= ." Immediately on startup

To get a good idea of how GC is performing turn on the GC logging in cassan= dra-env.sh. 

After a full cms GC event, see how big the tenured heap is. If it's no= t reducing enough then GC will never get far enough ahead. 

Cheers

-----------------
Aaron Morton
Freelance Cassandra Developer
New Zealand

@aaronmorton

On 22/02/2013, at 8:37 AM, Andras Szerdahelyi <andras.szerdahelyi@ignitionone.com>= ; wrote:

Thank you- indeed my index interval is 64 with a CF of 300M rows += bloom filter false positive chance was default.
Raising the index interval to 512 didn't fix this  alone, so I gu= ess I'll have to set the bloom filter to some reasonable value and scrub.

From: aaron morton <aaron@thelastpickle.com>
Reply-To: "user@cassandra.apache.org" <user@cassandra.apache.org>
Date: Thursday 21 February 2013 17:= 58
To: "user@cassandra.apache.org" <user@cassandra.apache.org>
Subject: Re: "Heap is N.N full= ." Immediately on startup

My first guess would be the bloom filter and index sampling from lots-o-row= s 

Check the row count in cfstats
Check the bloom filter size in cfstats. 


Cheers

-----------------
Aaron Morton
Freelance Cassandra Developer
New Zealand

@aaronmorton

On 20/02/2013, at 11:27 PM, Andras Szerdahelyi <andras.szerdahelyi@ignitionone.com&g= t; wrote:

Hey list,

Any ideas ( before I take a heap dump ) what might be consuming my 8GB= JVM heap at startup in Cassandra 1.1.6 besides
  • row cache : not persisted and is at 0 keys when this warning is produce= d
  • Memtables : no write traffic at startup, my app's column families= are durable_writes:false
  • Pending tasks : no pending tasks, except = for 928 compactions ( not sure where those are coming from )
I drew these conclusions from the StatusLogger output below: 

INFO [ScheduledTasks:1] 2013-02-20 05:13:25,198 GCInspector.java (line= 122) GC for ConcurrentMarkSweep: 14959 ms for 2 collections, 7017934560 us= ed; max is 8375238656
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,198 StatusLogger.jav= a (line 57) Pool Name               &nbs= p;    Active   Pending   Blocked
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,199 StatusLogger.jav= a (line 72) ReadStage               &nbs= p;         0         0    = ;     0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,200 StatusLogger.jav= a (line 72) RequestResponseStage             =  0         0         0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,200 StatusLogger.jav= a (line 72) ReadRepairStage              = ;     0         0        = 0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,200 StatusLogger.jav= a (line 72) MutationStage               =       0        -1       &= nbsp; 0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.jav= a (line 72) ReplicateOnWriteStage            = 0         0         0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.jav= a (line 72) GossipStage               &n= bsp;       0         0     &nb= sp;   0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.jav= a (line 72) AntiEntropyStage             &nbs= p;    0         0        = 0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.jav= a (line 72) MigrationStage              =      0         0       &= nbsp; 0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,201 StatusLogger.jav= a (line 72) StreamStage               &n= bsp;       0         0     &nb= sp;   0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.jav= a (line 72) MemtablePostFlusher             &= nbsp; 0         0         0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.jav= a (line 72) FlushWriter               &n= bsp;       0         0     &nb= sp;   0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.jav= a (line 72) MiscStage               &nbs= p;         0         0    = ;     0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,202 StatusLogger.jav= a (line 72) commitlog_archiver             &n= bsp;  0         0         0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,203 StatusLogger.jav= a (line 72) InternalResponseStage            = 0         0         0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.jav= a (line 77) CompactionManager             &nb= sp;   0       928
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.jav= a (line 89) MessagingService             &nbs= p;  n/a       0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.jav= a (line 99) Cache Type               &nb= sp;     Size               &nb= sp; Capacity               KeysToSave &n= bsp;                     =                      = ;             Provider
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,212 StatusLogger.jav= a (line 100) KeyCache               &nbs= p;         25            =           25           &= nbsp;          all         &nb= sp;                     &= nbsp;                    =             
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 106) RowCache               &nbs= p;          0           &= nbsp;            0        = ;              all       =        org.apache.cassandra.cache.SerializingCacheProvi= der
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 113) ColumnFamily               =  Memtable ops,data
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 116) MYAPP_1.CF               &n= bsp;        0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 116) MYAPP_2.CF             = ;            0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 116) HiveMetaStore.MetaStore           &nb= sp;       0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 116) system.NodeIdInfo             &n= bsp;           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 116) system.IndexInfo             &nb= sp;            0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,213 StatusLogger.jav= a (line 116) system.LocationInfo             =           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.Versions             &nbs= p;             0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.schema_keyspaces           &nb= sp;       0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.Migrations             &n= bsp;           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.schema_columnfamilies          = ;       0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.schema_columns            = ;         0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.HintsColumnFamily           &n= bsp;      0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) system.Schema              =               0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) cfs_archive.sblocks             =           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,214 StatusLogger.jav= a (line 116) cfs_archive.cleanup             =           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) cfs_archive.inode             &n= bsp;           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) cfs.cleanup               &= nbsp;               0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) cfs.sblocks               &= nbsp;               0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) cfs.inode               &nb= sp;                 0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) OpsCenter.events             &nb= sp;            0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) OpsCenter.rollups300            =          0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) OpsCenter.rollups86400           &nbs= p;        0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) OpsCenter.pdps              = ;        345,54448
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,215 StatusLogger.jav= a (line 116) OpsCenter.events_timeline           &= nbsp;     0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.jav= a (line 116) OpsCenter.settings             &= nbsp;          0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.jav= a (line 116) OpsCenter.rollups7200            = ;         0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.jav= a (line 116) OpsCenter.rollups60             =           0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.jav= a (line 116) demo.users               &n= bsp;                0,0
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,216 StatusLogger.jav= a (line 116) MYAPP_3.CF             = ;            0,0
 WARN [ScheduledTasks:1] 2013-02-20 05:13:25,216 GCInspector.java= (line 145) Heap is 0.8379384574280004 full.  You may need to reduce m= emtable and/or cache sizes.  Cassandra will now flush up to the two la= rgest memtables to free up memory.  Adjust flush_largest_memtables_at threshold in cassandra.yaml if you don't want Cassandra to do this automat= ically
 WARN [ScheduledTasks:1] 2013-02-20 05:13:25,217 StorageService.j= ava (line 2855) Flushing CFS(Keyspace=3D'OpsCenter', ColumnFamily=3D'pdps')= to relieve memory pressure
 INFO [ScheduledTasks:1] 2013-02-20 05:13:25,217 ColumnFamilyStor= e.java (line 659) Enqueuing flush of Memtable-pdps@98567689(15238/54448 ser= ialized/live bytes, 345 ops)
 INFO [FlushWriter:6] 2013-02-20 05:13:25,218 Memtable.java (line= 264) Writing Memtable-pdps@98567689(15238/54448 serialized/live bytes, 345= ops)
 INFO [FlushWriter:6] 2013-02-20 05:13:25,241 Memtable.java (line= 305) Completed flushing /var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-p= dps-hf-127-Data.db (5394 bytes) for commitlog position ReplayPosition(segme= ntId=3D1361354508149, :



Thanks!
Andras




 --_000_FE84AE7AAE9A2B4EA73512EED142BEF830CA4D0EATL02MB02corplo_--