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 13CFBD4D2 for ; Wed, 20 Feb 2013 10:27:42 +0000 (UTC) Received: (qmail 97995 invoked by uid 500); 20 Feb 2013 10:27:39 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 97804 invoked by uid 500); 20 Feb 2013 10:27:39 -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 97776 invoked by uid 99); 20 Feb 2013 10:27:38 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 20 Feb 2013 10:27:38 +0000 X-ASF-Spam-Status: No, hits=3.2 required=5.0 tests=HTML_MESSAGE,SPF_SOFTFAIL,UNPARSEABLE_RELAY X-Spam-Check-By: apache.org Received-SPF: softfail (nike.apache.org: transitioning domain of andras.szerdahelyi@ignitionone.com does not designate 216.82.254.106 as permitted sender) Received: from [216.82.254.106] (HELO mail1.bemta7.messagelabs.com) (216.82.254.106) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 20 Feb 2013 10:27:30 +0000 Received: from [216.82.254.195:5432] by server-10.bemta-7.messagelabs.com id F6/A2-11491-BF4A4215; Wed, 20 Feb 2013 10:27:07 +0000 X-Env-Sender: andras.szerdahelyi@ignitionone.com X-Msg-Ref: server-16.tower-200.messagelabs.com!1361356026!11445401!1 X-Originating-IP: [208.52.173.250] X-StarScan-Received: X-StarScan-Version: 6.8.6; banners=-,-,- X-VirusChecked: Checked Received: (qmail 17589 invoked from network); 20 Feb 2013 10:27:06 -0000 Received: from mail.dentsunetwork.com (HELO mail.dentsunetwork.com) (208.52.173.250) by server-16.tower-200.messagelabs.com with AES128-SHA encrypted SMTP; 20 Feb 2013 10:27:06 -0000 Received: from ATL02MB02.corp.local ([fe80::7997:c980:b031:df37]) by ATL02HUB02.corp.local ([::1]) with mapi id 14.02.0318.004; Wed, 20 Feb 2013 05:27:07 -0500 From: Andras Szerdahelyi To: "user@cassandra.apache.org" Subject: "Heap is N.N full." Immediately on startup Thread-Topic: "Heap is N.N full." Immediately on startup Thread-Index: AQHOD1TUBiFe5Uj7f0e3SMNkmloGrg== Date: Wed, 20 Feb 2013 10:27:05 +0000 Message-ID: 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_FE84AE7AAE9A2B4EA73512EED142BEF830C9901DATL02MB02corplo_" MIME-Version: 1.0 X-Virus-Checked: Checked by ClamAV on apache.org --_000_FE84AE7AAE9A2B4EA73512EED142BEF830C9901DATL02MB02corplo_ Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: quoted-printable 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_FE84AE7AAE9A2B4EA73512EED142BEF830C9901DATL02MB02corplo_ Content-Type: text/html; charset="us-ascii" Content-ID: Content-Transfer-Encoding: quoted-printable
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_FE84AE7AAE9A2B4EA73512EED142BEF830C9901DATL02MB02corplo_--