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 C5994106F3 for ; Wed, 4 Sep 2013 10:29:10 +0000 (UTC) Received: (qmail 15196 invoked by uid 500); 4 Sep 2013 10:29:08 -0000 Delivered-To: apmail-cassandra-user-archive@cassandra.apache.org Received: (qmail 15157 invoked by uid 500); 4 Sep 2013 10:29:07 -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 15136 invoked by uid 99); 4 Sep 2013 10:29:06 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 04 Sep 2013 10:29:06 +0000 X-ASF-Spam-Status: No, hits=-0.0 required=5.0 tests=RCVD_IN_DNSWL_NONE,SPF_HELO_PASS X-Spam-Check-By: apache.org Received-SPF: error (athena.apache.org: local policy) Received: from [212.227.126.186] (HELO moutng.kundenserver.de) (212.227.126.186) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 04 Sep 2013 10:29:00 +0000 Received: from [172.20.10.5] (tmo-106-238.customers.d1-online.com [80.187.106.238]) by mrelayeu.kundenserver.de (node=mreu2) with ESMTP (Nemesis) id 0MDkte-1VDMOA4Bg6-00HNsh; Wed, 04 Sep 2013 12:28:18 +0200 Content-Type: text/plain; charset=us-ascii Mime-Version: 1.0 (Mac OS X Mail 6.5 \(1508\)) Subject: Re: Cassandra shuts down; was:Cassandra crashes From: Jan Algermissen In-Reply-To: Date: Wed, 4 Sep 2013 12:25:16 +0200 Content-Transfer-Encoding: quoted-printable Message-Id: <6C63C1AE-4F0E-4B24-9F66-89C53FEEFDC6@nordsc.com> References: To: user@cassandra.apache.org X-Mailer: Apple Mail (2.1508) X-Provags-ID: V02:K0:YGRRRWp7lthUzvDy9NqqQ7WfSVzpKjxt2Y3oRHBSY+3 jKKXpFe+RCAHyL5WbKFuK5Tu/rL6sOnTccHIsKWlXmjUDwvgpd Wd2EPWz4fSD/orfV7zsucjnHe3dX1KqE7jM1AVQAa5i0WmCmxW TSvM0na2L8XANyXgjRn1PCfEdqMAvKj//xu34Kf+mHsE6egyUl zqLBXoVS+N42etyyBdEv6EbPBJesuLOgjoWcuIL/oftyV9hJSi 8ejd6ahhqaNriujjCMZxDVKxvyLgy1arimo0luCwCZSDO4tiBL lfOkqyo81hno2qbKCRTupdNpRsKZqUgJECfLw/nrkgXYbP8gTc wnKgLsqhwIfUBDeSzr+LWKcJPvmepLwTpeca53ineyCIQnaA+h 4riac8+5PVFpj+Z3q48d7YrECU16msn59M= X-Virus-Checked: Checked by ClamAV on apache.org Romain, On 04.09.2013, at 11:11, Romain HARDOUIN = wrote: > Maybe you should include the end of Cassandra logs.=20 There is nothing that seems interesting in cassandra.log. Below you find = system.log. > What comes to my mind when I read your first post is OOM killer.=20 > But what you describe later is not the case.=20 > Just to be sure, have you checked /var/log/messages?=20 Nothing there, just occasional Firewall TCP rejections.=20 Somehow I think I am simply overloading the whole cluster (see the = hinted handoff messages in the log). Could that be due to the limited = memory of 2GB my nodes have? IOW, not enough space to buffer up the = writes before dumping to disk? Also, my overall write performance is actually pretty bad compared to = what I read about C*. Before I thought it was the client doing to much = work or the network. Turns out that's not the case. I'd expect C* to sort of just suck in my rather small amount of data - = must be me, not using the right configuration. Oh well, I'll get there = :-) Thanks anyhow. Jan >=20 > Romain=20 >=20 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,057 StatusLogger.java (line = 96) KeyCache 216 936 = all = =20 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,057 StatusLogger.java (line = 102) RowCache 0 0 = all = org.apache.cassandra.cache.SerializingCacheProvider INFO [ScheduledTasks:1] 2013-09-04 07:17:09,058 StatusLogger.java (line = 109) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2013-09-04 07:17:09,082 StatusLogger.java (line = 112) system.local 4,52 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,083 StatusLogger.java (line = 112) system.peers 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,083 StatusLogger.java (line = 112) system.batchlog 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,083 StatusLogger.java (line = 112) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,083 StatusLogger.java (line = 112) system.LocationInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,084 StatusLogger.java (line = 112) system.Schema 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,084 StatusLogger.java (line = 112) system.Migrations 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,084 StatusLogger.java (line = 112) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,084 StatusLogger.java (line = 112) system.schema_columns 0,0 ERROR [FlushWriter:6] 2013-09-04 07:17:09,210 CassandraDaemon.java (line = 192) Exception in thread Thread[FlushWriter:6,5,main] java.lang.OutOfMemoryError: Java heap space at = org.apache.cassandra.io.util.FastByteArrayOutputStream.expand(FastByteArra= yOutputStream.java:104) at = org.apache.cassandra.io.util.FastByteArrayOutputStream.write(FastByteArray= OutputStream.java:220) at java.io.DataOutputStream.write(DataOutputStream.java:107) at = org.apache.cassandra.io.util.DataOutputBuffer.write(DataOutputBuffer.java:= 60) at = org.apache.cassandra.utils.ByteBufferUtil.write(ByteBufferUtil.java:328) at = org.apache.cassandra.utils.ByteBufferUtil.writeWithLength(ByteBufferUtil.j= ava:315) at = org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java:5= 5) at = org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java:3= 0) at = org.apache.cassandra.db.OnDiskAtom$Serializer.serializeForSSTable(OnDiskAt= om.java:62) at = org.apache.cassandra.db.ColumnIndex$Builder.add(ColumnIndex.java:181) at = org.apache.cassandra.db.ColumnIndex$Builder.build(ColumnIndex.java:133) at = org.apache.cassandra.io.sstable.SSTableWriter.append(SSTableWriter.java:18= 5) at = org.apache.cassandra.db.Memtable$FlushRunnable.writeSortedContents(Memtabl= e.java:489) at = org.apache.cassandra.db.Memtable$FlushRunnable.runWith(Memtable.java:448) at = org.apache.cassandra.io.util.DiskAwareRunnable.runMayThrow(DiskAwareRunnab= le.java:48) at = org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28) at = java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:= 1145) at = java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java= :615) at java.lang.Thread.run(Thread.java:724) INFO [ScheduledTasks:1] 2013-09-04 07:17:09,210 StatusLogger.java (line = 112) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,218 StatusLogger.java (line = 112) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,218 StatusLogger.java (line = 112) system.range_xfers 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,219 StatusLogger.java (line = 112) system.peer_events 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,219 StatusLogger.java (line = 112) system.hints 1524,9518677 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,219 StatusLogger.java (line = 112) system.HintsColumnFamily 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,219 StatusLogger.java (line = 112) products.product 89984,7340032 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,220 StatusLogger.java (line = 112) products.user 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,220 StatusLogger.java (line = 112) products.y 0,0 INFO [FlushWriter:7] 2013-09-04 07:17:09,222 Memtable.java (line 461) = Writing Memtable-product@1877827562(140596898/128974848 serialized/live = bytes, 1982097 ops) INFO [ScheduledTasks:1] 2013-09-04 07:17:09,225 StatusLogger.java (line = 112) system_auth.users 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,228 StatusLogger.java (line = 112) system_traces.sessions 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,228 StatusLogger.java (line = 112) system_traces.events 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,229 GCInspector.java (line = 119) GC for ConcurrentMarkSweep: 7532 ms for 4 collections, 973781352 = used; max is 1031798784 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,230 StatusLogger.java (line = 53) Pool Name Active Pending Blocked INFO [ScheduledTasks:1] 2013-09-04 07:17:09,230 StatusLogger.java (line = 68) ReadStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,231 StatusLogger.java (line = 68) RequestResponseStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,231 StatusLogger.java (line = 68) ReadRepairStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,232 StatusLogger.java (line = 68) MutationStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,243 StatusLogger.java (line = 68) ReplicateOnWriteStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,244 StatusLogger.java (line = 68) GossipStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,245 StatusLogger.java (line = 68) AntiEntropyStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,245 StatusLogger.java (line = 68) MigrationStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,246 StatusLogger.java (line = 68) MemtablePostFlusher 1 5 0 INFO [StorageServiceShutdownHook] 2013-09-04 07:17:09,262 = ThriftServer.java (line 116) Stop listening to thrift clients INFO [ScheduledTasks:1] 2013-09-04 07:17:09,264 StatusLogger.java (line = 68) FlushWriter 1 4 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,300 StatusLogger.java (line = 68) MiscStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,301 StatusLogger.java (line = 68) commitlog_archiver 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,301 StatusLogger.java (line = 68) InternalResponseStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,301 StatusLogger.java (line = 68) HintedHandoff 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,302 StatusLogger.java (line = 73) CompactionManager 2 4 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,307 StatusLogger.java (line = 85) MessagingService n/a 181,1 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,336 StatusLogger.java (line = 95) Cache Type Size Capacity = KeysToSave = Provider INFO [ScheduledTasks:1] 2013-09-04 07:17:09,338 StatusLogger.java (line = 96) KeyCache 216 936 = all = =20 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,338 StatusLogger.java (line = 102) RowCache 0 0 = all = org.apache.cassandra.cache.SerializingCacheProvider INFO [ScheduledTasks:1] 2013-09-04 07:17:09,388 StatusLogger.java (line = 109) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2013-09-04 07:17:09,391 StatusLogger.java (line = 112) system.local 4,52 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,391 StatusLogger.java (line = 112) system.peers 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,392 StatusLogger.java (line = 112) system.batchlog 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,392 StatusLogger.java (line = 112) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,392 StatusLogger.java (line = 112) system.LocationInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,393 StatusLogger.java (line = 112) system.Schema 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,393 StatusLogger.java (line = 112) system.Migrations 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,479 StatusLogger.java (line = 112) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,480 StatusLogger.java (line = 112) system.schema_columns 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,481 StatusLogger.java (line = 112) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,482 StatusLogger.java (line = 112) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,483 StatusLogger.java (line = 112) system.range_xfers 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,483 StatusLogger.java (line = 112) system.peer_events 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,483 StatusLogger.java (line = 112) system.hints 1540,9611391 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,484 StatusLogger.java (line = 112) system.HintsColumnFamily 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,484 StatusLogger.java (line = 112) products.product 92447,7340032 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,555 StatusLogger.java (line = 112) products.user 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,556 StatusLogger.java (line = 112) products.y 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,556 StatusLogger.java (line = 112) system_auth.users 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,556 StatusLogger.java (line = 112) system_traces.sessions 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:09,574 StatusLogger.java (line = 112) system_traces.events 0,0 WARN [ScheduledTasks:1] 2013-09-04 07:17:09,574 GCInspector.java (line = 142) Heap is 0.9437705947131645 full. You may need to reduce memtable = and/or cache sizes. Cassandra will now flush up to the two largest = memtables to free up memory. Adjust flush_largest_memtables_at = threshold in cassandra.yaml if you don't want Cassandra to do this = automatically WARN [ScheduledTasks:1] 2013-09-04 07:17:09,575 StorageService.java = (line 3618) Flushing CFS(Keyspace=3D'system', ColumnFamily=3D'hints') to = relieve memory pressure INFO [ScheduledTasks:1] 2013-09-04 07:17:11,990 ColumnFamilyStore.java = (line 630) Enqueuing flush of Memtable-hints@1707891156(9668763/9668763 = serialized/live bytes, 1549 ops) INFO [StorageServiceShutdownHook] 2013-09-04 07:17:12,188 Server.java = (line 151) Stop listening for CQL clients INFO [StorageServiceShutdownHook] 2013-09-04 07:17:12,188 Gossiper.java = (line 1122) Announcing shutdown INFO [ScheduledTasks:1] 2013-09-04 07:17:12,992 GCInspector.java (line = 119) GC for ConcurrentMarkSweep: 2409 ms for 1 collections, 917569968 = used; max is 1031798784 INFO [ScheduledTasks:1] 2013-09-04 07:17:12,993 StatusLogger.java (line = 53) Pool Name Active Pending Blocked INFO [ScheduledTasks:1] 2013-09-04 07:17:12,994 StatusLogger.java (line = 68) ReadStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:12,996 StatusLogger.java (line = 68) RequestResponseStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:12,997 StatusLogger.java (line = 68) ReadRepairStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:12,997 StatusLogger.java (line = 68) MutationStage 0 1 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:12,998 StatusLogger.java (line = 68) ReplicateOnWriteStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:12,999 StatusLogger.java (line = 68) GossipStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,011 StatusLogger.java (line = 68) AntiEntropyStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,012 StatusLogger.java (line = 68) MigrationStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,013 StatusLogger.java (line = 68) MemtablePostFlusher 1 6 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,013 StatusLogger.java (line = 68) FlushWriter 1 5 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,014 StatusLogger.java (line = 68) MiscStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,015 StatusLogger.java (line = 68) commitlog_archiver 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,016 StatusLogger.java (line = 68) InternalResponseStage 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,026 StatusLogger.java (line = 68) HintedHandoff 0 0 0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,027 StatusLogger.java (line = 73) CompactionManager 2 4 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,027 StatusLogger.java (line = 85) MessagingService n/a 0,2 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,028 StatusLogger.java (line = 95) Cache Type Size Capacity = KeysToSave = Provider INFO [ScheduledTasks:1] 2013-09-04 07:17:13,073 StatusLogger.java (line = 96) KeyCache 216 936 = all = =20 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,074 StatusLogger.java (line = 102) RowCache 0 0 = all = org.apache.cassandra.cache.SerializingCacheProvider INFO [ScheduledTasks:1] 2013-09-04 07:17:13,074 StatusLogger.java (line = 109) ColumnFamily Memtable ops,data INFO [ScheduledTasks:1] 2013-09-04 07:17:13,076 StatusLogger.java (line = 112) system.local 4,52 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,077 StatusLogger.java (line = 112) system.peers 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,077 StatusLogger.java (line = 112) system.batchlog 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,078 StatusLogger.java (line = 112) system.NodeIdInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,078 StatusLogger.java (line = 112) system.LocationInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,079 StatusLogger.java (line = 112) system.Schema 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,083 StatusLogger.java (line = 112) system.Migrations 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,083 StatusLogger.java (line = 112) system.schema_keyspaces 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,084 StatusLogger.java (line = 112) system.schema_columns 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,084 StatusLogger.java (line = 112) system.schema_columnfamilies 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,085 StatusLogger.java (line = 112) system.IndexInfo 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,085 StatusLogger.java (line = 112) system.range_xfers 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,086 StatusLogger.java (line = 112) system.peer_events 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,086 StatusLogger.java (line = 112) system.hints 9,52886 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,086 StatusLogger.java (line = 112) system.HintsColumnFamily 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,087 StatusLogger.java (line = 112) products.product 153502,11534336 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,093 StatusLogger.java (line = 112) products.user 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,095 StatusLogger.java (line = 112) products.y 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,096 StatusLogger.java (line = 112) system_auth.users 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,098 StatusLogger.java (line = 112) system_traces.sessions 0,0 INFO [ScheduledTasks:1] 2013-09-04 07:17:13,098 StatusLogger.java (line = 112) system_traces.events 0,0 WARN [ScheduledTasks:1] 2013-09-04 07:17:13,101 GCInspector.java (line = 142) Heap is 0.8892915772228707 full. You may need to reduce memtable = and/or cache sizes. Cassandra will now flush up to the two largest = memtables to free up memory. Adjust flush_largest_memtables_at = threshold in cassandra.yaml if you don't want Cassandra to do this = automatically WARN [ScheduledTasks:1] 2013-09-04 07:17:13,101 StorageService.java = (line 3618) Flushing CFS(Keyspace=3D'products', ColumnFamily=3D'product') = to relieve memory pressure INFO [ScheduledTasks:1] 2013-09-04 07:17:13,107 ColumnFamilyStore.java = (line 630) Enqueuing flush of = Memtable-product@1107806067(11494898/11534336 serialized/live bytes, = 155140 ops) INFO [StorageServiceShutdownHook] 2013-09-04 07:17:14,189 = MessagingService.java (line 685) Waiting for messaging service to = quiesce INFO [ACCEPT-/82.196.1.207] 2013-09-04 07:17:14,190 = MessagingService.java (line 895) MessagingService shutting down server = thread. INFO [FlushWriter:7] 2013-09-04 07:17:25,219 Memtable.java (line 495) = Completed flushing = /var/lib/cassandra/data/products/product/products-product-ic-442-Data.db = (37718870 bytes) for commitlog position = ReplayPosition(segmentId=3D1378271785146, position=3D20998285) INFO [FlushWriter:7] 2013-09-04 07:17:25,232 Memtable.java (line 461) = Writing Memtable-hints@887419340(30631648/30631648 serialized/live = bytes, 5011 ops) ----------------------------------------------------- WARN [ScheduledTasks:1] 2013-09-04 06:40:15,772 GCInspector.java (line = 136) Heap is 0.9995487569793453 full. You may need to reduce memtable = and/or cache sizes. Cassandra is now reducing cache sizes to free up = memory. Adjust reduce_cache_sizes_at threshold in cassandra.yaml if you = don't want Cassandra to do this automatically WARN [ScheduledTasks:1] 2013-09-04 06:40:15,773 AutoSavingCache.java = (line 185) Reducing KeyCache capacity from 51380224 to 96830 to reduce = memory pressure WARN [ScheduledTasks:1] 2013-09-04 06:40:15,774 GCInspector.java (line = 142) Heap is 0.9995487569793453 full. You may need to reduce memtable = and/or cache sizes. Cassandra will now flush up to the two largest = memtables to free up memory. Adjust flush_largest_memtables_at = threshold in cassandra.yaml if you don't want Cassandra to do this = automatically WARN [ScheduledTasks:1] 2013-09-04 06:40:15,774 StorageService.java = (line 3618) Flushing CFS(Keyspace=3D'system', ColumnFamily=3D'hints') to = relieve memory pressure INFO [HANDSHAKE-/37.139.24.133] 2013-09-04 06:40:15,791 = OutboundTcpConnection.java (line 399) Handshaking version with = /37.139.24.133 INFO [HANDSHAKE-/37.139.24.133] 2013-09-04 06:40:15,809 = OutboundTcpConnection.java (line 399) Handshaking version with = /37.139.24.133 INFO [HANDSHAKE-/37.139.24.133] 2013-09-04 06:40:15,887 = OutboundTcpConnection.java (line 399) Handshaking version with = /37.139.24.133 WARN [Native-Transport-Requests:965] 2013-09-04 06:40:21,117 = Slf4JLogger.java (line 76) An exception was thrown by a user handler = while handling an exception event ([id: 0x8ecd02f0, /37.139.31.126:60608 = :> /146.185.135.226:9042] EXCEPTION: java.lang.AssertionError: = java.lang.InterruptedException) java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has = shut down at = org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExe= cution(DebuggableThreadPoolExecutor.java:61) at = java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821= ) at = java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:13= 72) at = org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor.execute(Debug= gableThreadPoolExecutor.java:145) at = org.jboss.netty.handler.execution.ExecutionHandler.handleUpstream(Executio= nHandler.java:172) at = org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToO= neDecoder.java:61) at = org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToO= neDecoder.java:61) at = org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDeco= der.java:378) at org.jboss. [... more stack trace ...] WARN [Native-Transport-Requests:965] 2013-09-04 06:40:25,878 = Slf4JLogger.java (line 76) An exception was thrown by a user handler = while handling an exception event ([id: 0x8ecd02f0, /37.139.31.126:60608 = :> /146.185.135.226:9042] EXCEPTION: java.lang.AssertionError: = java.lang.InterruptedException) java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has = shut down at = org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExe= cution(DebuggableThreadPoolExecutor.java:61) at = java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821= ) at = java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:13= 72) at = org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor.execute(Debug= gableThreadPoolExecutor.java:145) at = org.jboss.netty.handler.execution.ExecutionHandler.handleUpstream(Executio= nHandler.java:172) at = org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToO= neDecoder.java:61) at = org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToO= neDecoder.java:61) at = org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDeco= der.java:378) at = org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533) at org.jboss.netty.channel.Channels$7.run(Channels.java:507) at = org.jboss.netty.channel.socket.ChannelRunnableWrapper.run(ChannelRunnableW= rapper.java:41) at = org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(Abs= tractNioWorker.java:407) at = org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.j= ava:35) at = org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(Abs= tractNioWorker.java:379) at = org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.j= ava:35) at = org.jboss.netty.channel.socket.nio.AbstractNioChannelSink.execute(Abstract= NioChannelSink.java:34) at = org.jboss.netty.channel.Channels.fireExceptionCaughtLater(Channels.java:50= 4) at = org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChanne= lSink.java:47) at = org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(Chann= elUpstreamEventRunnable.java:45) at = org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRun= nable.java:69) at = java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:= 1145) at = java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java= :615) at java.lang.Thread.run(Thread.java:724) INFO [StorageServiceShutdownHook] 2013-09-04 06:40:25,923 Server.java = (line 151) Stop listening for CQL clients INFO [StorageServiceShutdownHook] 2013-09-04 06:40:25,924 Gossiper.java = (line 1122) Announcing shutdown INFO [StorageServiceShutdownHook] 2013-09-04 06:40:29,348 = MessagingService.java (line 685) Waiting for messaging service to = quiesce INFO [ACCEPT-/146.185.135.226] 2013-09-04 06:40:29,355 = MessagingService.java (line 895) MessagingService shutting down server = thread. INFO [HintedHandoff:2] 2013-09-04 06:40:59,235 = HintedHandOffManager.java (line 418) Timed out replaying hints to = /82.196.1.207; aborting (0 delivered) INFO [FlushWriter:127] 2013-09-04 06:43:14,080 Memtable.java (line 495) = Completed flushing = /var/lib/cassandra/data/products/product/products-product-ic-296-Data.db = (11135924 bytes) for commitlog position = ReplayPosition(segmentId=3D1378049078572, position=3D23650216) INFO [FlushWriter:127] 2013-09-04 06:43:14,109 Memtable.java (line 461) = Writing Memtable-product@800619397(36612976/34603008 serialized/live = bytes, 501581 ops) INFO [FlushWriter:127] 2013-09-04 06:43:50,826 Memtable.java (line 495) = Completed flushing = /var/lib/cassandra/data/products/product/products-product-ic-297-Data.db = (10377307 bytes) for commitlog position = ReplayPosition(segmentId=3D1378049078574, position=3D1219563) INFO [FlushWriter:127] 2013-09-04 06:43:50,854 Memtable.java (line 461) = Writing Memtable-product@2016963286(25537061/24117248 serialized/live = bytes, 329765 ops) INFO [CompactionExecutor:222] 2013-09-04 06:43:50,858 = CompactionTask.java (line 105) Compacting = [SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-p= roduct-ic-297-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-292-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-296-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-294-Data.db')] INFO [FlushWriter:127] 2013-09-04 06:44:10,401 Memtable.java (line 495) = Completed flushing = /var/lib/cassandra/data/products/product/products-product-ic-298-Data.db = (7082158 bytes) for commitlog position = ReplayPosition(segmentId=3D1378049078574, position=3D31970427) INFO [FlushWriter:127] 2013-09-04 06:44:10,442 Memtable.java (line 461) = Writing Memtable-product@980202276(5866214/6291456 serialized/live = bytes, 79296 ops) INFO [FlushWriter:127] 2013-09-04 06:44:15,308 Memtable.java (line 495) = Completed flushing = /var/lib/cassandra/data/products/product/products-product-ic-300-Data.db = (1725129 bytes) for commitlog position = ReplayPosition(segmentId=3D1378049078575, position=3D5562931) INFO [FlushWriter:127] 2013-09-04 06:44:15,309 Memtable.java (line 461) = Writing Memtable-product@1335531705(45116775/42991616 serialized/live = bytes, 622343 ops) INFO [FlushWriter:127] 2013-09-04 06:44:52,124 Memtable.java (line 495) = Completed flushing = /var/lib/cassandra/data/products/product/products-product-ic-301-Data.db = (12793982 bytes) for commitlog position = ReplayPosition(segmentId=3D1378049078576, position=3D28462140) INFO [CompactionExecutor:222] 2013-09-04 07:02:09,277 = CompactionTask.java (line 262) Compacted 4 sstables to = [/var/lib/cassandra/data/products/product/products-product-ic-299,]. = 65,775,866 bytes to 46,875,492 (~71% of original) in 1,098,419ms =3D = 0.040698MB/s. 8,553 total rows, 5,403 unique. Row merge counts were = {1:2538, 2:2580, 3:285, 4:0, } INFO [CompactionExecutor:223] 2013-09-04 07:02:09,399 = CompactionTask.java (line 105) Compacting = [SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-p= roduct-ic-299-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-298-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-301-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-300-Data.db')] INFO [CompactionExecutor:223] 2013-09-04 07:22:11,234 = CompactionTask.java (line 262) Compacted 4 sstables to = [/var/lib/cassandra/data/products/product/products-product-ic-302,]. = 68,476,761 bytes to 53,738,703 (~78% of original) in 1,201,835ms =3D = 0.042642MB/s. 9,076 total rows, 6,753 unique. Row merge counts were = {1:4864, 2:1470, 3:404, 4:15, } INFO [CompactionExecutor:224] 2013-09-04 07:22:11,317 = CompactionTask.java (line 105) Compacting = [SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-p= roduct-ic-274-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-293-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-265-Data.db'), = SSTableReader(path=3D'/var/lib/cassandra/data/products/product/products-pr= oduct-ic-302-Data.db')] WARN [StorageServiceShutdownHook] 2013-09-04 07:40:29,355 = StorageProxy.java (line 1697) Some hints were not written before = shutdown. This is not supposed to happen. You should (a) run repair, = and (b) file a bug report