Romain,
On 04.09.2013, at 11:11, Romain HARDOUIN <romain.hardo...@urssaf.fr> wrote:
> Maybe you should include the end of Cassandra logs.
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.
> But what you describe later is not the case.
> Just to be sure, have you checked /var/log/messages?
Nothing there, just occasional Firewall TCP rejections.
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
>
> Romain
>
INFO [ScheduledTasks:1] 2013-09-04 07:17:09,057 StatusLogger.java (line 96)
KeyCache 216 936
all
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(FastByteArrayOutputStream.java:104)
at
org.apache.cassandra.io.util.FastByteArrayOutputStream.write(FastByteArrayOutputStream.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.java:315)
at
org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java:55)
at
org.apache.cassandra.db.ColumnSerializer.serialize(ColumnSerializer.java:30)
at
org.apache.cassandra.db.OnDiskAtom$Serializer.serializeForSSTable(OnDiskAtom.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:185)
at
org.apache.cassandra.db.Memtable$FlushRunnable.writeSortedContents(Memtable.java:489)
at
org.apache.cassandra.db.Memtable$FlushRunnable.runWith(Memtable.java:448)
at
org.apache.cassandra.io.util.DiskAwareRunnable.runMayThrow(DiskAwareRunnable.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
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='system', ColumnFamily='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
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='products', ColumnFamily='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=1378271785146,
position=20998285)
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='system', ColumnFamily='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.rejectedExecution(DebuggableThreadPoolExecutor.java:61)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor.execute(DebuggableThreadPoolExecutor.java:145)
at
org.jboss.netty.handler.execution.ExecutionHandler.handleUpstream(ExecutionHandler.java:172)
at
org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:61)
at
org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:61)
at
org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.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.rejectedExecution(DebuggableThreadPoolExecutor.java:61)
at
java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:821)
at
java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1372)
at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor.execute(DebuggableThreadPoolExecutor.java:145)
at
org.jboss.netty.handler.execution.ExecutionHandler.handleUpstream(ExecutionHandler.java:172)
at
org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:61)
at
org.jboss.netty.handler.codec.oneone.OneToOneDecoder.handleUpstream(OneToOneDecoder.java:61)
at
org.jboss.netty.handler.codec.frame.FrameDecoder.exceptionCaught(FrameDecoder.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(ChannelRunnableWrapper.java:41)
at
org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(AbstractNioWorker.java:407)
at
org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.java:35)
at
org.jboss.netty.channel.socket.nio.AbstractNioWorker.executeInIoThread(AbstractNioWorker.java:379)
at
org.jboss.netty.channel.socket.nio.NioWorker.executeInIoThread(NioWorker.java:35)
at
org.jboss.netty.channel.socket.nio.AbstractNioChannelSink.execute(AbstractNioChannelSink.java:34)
at
org.jboss.netty.channel.Channels.fireExceptionCaughtLater(Channels.java:504)
at
org.jboss.netty.channel.AbstractChannelSink.exceptionCaught(AbstractChannelSink.java:47)
at
org.jboss.netty.handler.execution.ChannelUpstreamEventRunnable.doRun(ChannelUpstreamEventRunnable.java:45)
at
org.jboss.netty.handler.execution.ChannelEventRunnable.run(ChannelEventRunnable.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=1378049078572,
position=23650216)
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=1378049078574,
position=1219563)
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='/var/lib/cassandra/data/products/product/products-product-ic-297-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-ic-292-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-ic-296-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-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=1378049078574,
position=31970427)
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=1378049078575,
position=5562931)
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=1378049078576,
position=28462140)
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 =
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='/var/lib/cassandra/data/products/product/products-product-ic-299-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-ic-298-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-ic-301-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-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 =
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='/var/lib/cassandra/data/products/product/products-product-ic-274-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-ic-293-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-ic-265-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/products/product/products-product-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
