incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robin Verlangen <ro...@us2.nl>
Subject Cassandra OOM crash while mapping commitlog
Date Sat, 11 Aug 2012 16:59:07 GMT
Hi there,

I currently see Cassandra crash every couple of days. I run a 3 node
cluster on version 1.1.2. Does anyone have a clue why it crashes? I
couldn't find it as fix in a newer release. Is this an actual bug or did I
do something wrong?

Thank you in advance for your time.

Last 100 log lines before crash:

* INFO [FlushWriter:39] 2012-08-11 12:51:00,933 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-7-Data.db
(10778171 bytes) for commitlog position
ReplayPosition(segmentId=2831860362157183, position=89962041)*
* INFO [OptionalTasks:1] 2012-08-11 13:12:30,940 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='CloudPelican',
ColumnFamily='wordevents') (estimated 74393593 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 13:12:30,941 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-wordevents@32552383(22883734/74393593
serialized/live bytes, 227279 ops)*
* INFO [FlushWriter:40] 2012-08-11 13:12:30,941 Memtable.java (line 266)
Writing Memtable-wordevents@32552383(22883734/74393593 serialized/live
bytes, 227279 ops)*
* INFO [FlushWriter:40] 2012-08-11 13:12:31,703 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-158-Data.db
(11800327 bytes) for commitlog position
ReplayPosition(segmentId=2831860362157183, position=116934579)*
* INFO [MemoryMeter:1] 2012-08-11 14:01:36,942 Memtable.java (line 213)
CFS(Keyspace='OpsCenter', ColumnFamily='rollups7200') liveRatio is
6.158919689235077 (just-counted was 4.408341190092955).  calculation took
100ms for 16409 columns*
* INFO [CompactionExecutor:88] 2012-08-11 14:08:27,875 AutoSavingCache.java
(line 262) Saved KeyCache (38164 items) in 70 ms*
* INFO [OptionalTasks:1] 2012-08-11 14:18:37,519 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='CloudPelican',
ColumnFamily='wordevents') (estimated 74346493 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 14:18:37,519 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-wordevents@10789879(22869246/74346493
serialized/live bytes, 226341 ops)*
* INFO [FlushWriter:41] 2012-08-11 14:18:37,520 Memtable.java (line 266)
Writing Memtable-wordevents@10789879(22869246/74346493 serialized/live
bytes, 226341 ops)*
* INFO [FlushWriter:41] 2012-08-11 14:18:38,288 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-159-Data.db
(11796722 bytes) for commitlog position
ReplayPosition(segmentId=2838466681767183, position=67094743)*
* WARN [MemoryMeter:1] 2012-08-11 14:21:55,676 Memtable.java (line 197)
setting live ratio to minimum of 1.0 instead of 0.45760196307363504*
* INFO [MemoryMeter:1] 2012-08-11 14:21:55,676 Memtable.java (line 213)
CFS(Keyspace='Wupa', ColumnFamily='PageViewsHost') liveRatio is
1.0421914932457101 (just-counted was 1.0).  calculation took 2ms for 175
columns*
* INFO [MemoryMeter:1] 2012-08-11 14:33:20,916 Memtable.java (line 213)
CFS(Keyspace='OpsCenter', ColumnFamily='rollups60') liveRatio is
4.067582667928898 (just-counted was 4.031462910772899).  calculation took
711ms for 169224 columns*
* INFO [OptionalTasks:1] 2012-08-11 14:59:20,909 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='OpsCenter',
ColumnFamily='pdps') (estimated 74395427 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 14:59:20,909 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-pdps@30500189(9222554/74395427
serialized/live bytes, 214478 ops)*
* INFO [FlushWriter:42] 2012-08-11 14:59:20,910 Memtable.java (line 266)
Writing Memtable-pdps@30500189(9222554/74395427 serialized/live bytes,
214478 ops)*
* INFO [FlushWriter:42] 2012-08-11 14:59:21,420 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11351-Data.db
(6928124 bytes) for commitlog position
ReplayPosition(segmentId=2838466681767183, position=117115966)*
* INFO [MemoryMeter:1] 2012-08-11 14:59:31,138 Memtable.java (line 213)
CFS(Keyspace='OpsCenter', ColumnFamily='pdps') liveRatio is
14.460953759840738 (just-counted was 14.460953759840738).  calculation took
28ms for 878 columns*
* INFO [OptionalTasks:1] 2012-08-11 15:25:41,366 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='CloudPelican',
ColumnFamily='wordevents') (estimated 74974061 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 15:25:41,367 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-wordevents@24703812(23062288/74974061
serialized/live bytes, 228878 ops)*
* INFO [FlushWriter:43] 2012-08-11 15:25:41,367 Memtable.java (line 266)
Writing Memtable-wordevents@24703812(23062288/74974061 serialized/live
bytes, 228878 ops)*
* INFO [FlushWriter:43] 2012-08-11 15:25:42,144 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-160-Data.db
(11891766 bytes) for commitlog position
ReplayPosition(segmentId=2844308891384183, position=29935798)*
* INFO [OptionalTasks:1] 2012-08-11 15:50:30,630 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='CloudPelican',
ColumnFamily='events') (estimated 74318657 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 15:50:30,631 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-events@6204038(14756712/74318657
serialized/live bytes, 224254 ops)*
* INFO [FlushWriter:44] 2012-08-11 15:50:30,631 Memtable.java (line 266)
Writing Memtable-events@6204038(14756712/74318657 serialized/live bytes,
224254 ops)*
* INFO [FlushWriter:44] 2012-08-11 15:50:31,428 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/CloudPelican/events/CloudPelican-events-hd-97-Data.db
(5654663 bytes) for commitlog position
ReplayPosition(segmentId=2844308891384183, position=65470717)*
* INFO [OptionalTasks:1] 2012-08-11 15:59:32,864 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='OpsCenter',
ColumnFamily='pdps') (estimated 74304013 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 15:59:32,864 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-pdps@14242177(4110601/74304013
serialized/live bytes, 95731 ops)*
* INFO [FlushWriter:45] 2012-08-11 15:59:32,865 Memtable.java (line 266)
Writing Memtable-pdps@14242177(4110601/74304013 serialized/live bytes,
95731 ops)*
* INFO [FlushWriter:45] 2012-08-11 15:59:33,117 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11352-Data.db
(3190253 bytes) for commitlog position
ReplayPosition(segmentId=2844308891384183, position=81207982)*
* INFO [OptionalTasks:1] 2012-08-11 16:14:00,792 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='OpsCenter',
ColumnFamily='rollups60') (estimated 72855795 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 16:14:00,793 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-rollups60@6896103(14329060/72855795
serialized/live bytes, 334552 ops)*
* INFO [FlushWriter:46] 2012-08-11 16:14:00,793 Memtable.java (line 266)
Writing Memtable-rollups60@6896103(14329060/72855795 serialized/live bytes,
334552 ops)*
* INFO [MemoryMeter:1] 2012-08-11 16:14:01,140 Memtable.java (line 213)
CFS(Keyspace='CloudPelican', ColumnFamily='wordevents') liveRatio is
2.174146758479727 (just-counted was 1.7475433700933507).  calculation took
792ms for 185473 columns*
* INFO [FlushWriter:46] 2012-08-11 16:14:01,627 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-8-Data.db
(10595913 bytes) for commitlog position
ReplayPosition(segmentId=2844308891384183, position=104879371)*
* INFO [CompactionExecutor:94] 2012-08-11 16:14:01,629 CompactionTask.java
(line 109) Compacting
[SSTableReader(path='/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-7-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-6-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-5-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-8-Data.db')]
*
* INFO [CompactionExecutor:94] 2012-08-11 16:14:07,291 CompactionTask.java
(line 221) Compacted to
[/var/lib/cassandra/data/OpsCenter/rollups60/OpsCenter-rollups60-hd-9-Data.db,].
 72,023,724 to 71,518,964 (~99% of original) bytes for 1,692 keys at
12.046238MB/s.  Time: 5,662ms.*
* INFO [OptionalTasks:1] 2012-08-11 16:38:47,081 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='CloudPelican',
ColumnFamily='wordevents') (estimated 74301547 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 16:38:47,082 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-wordevents@29484922(27340030/74301547
serialized/live bytes, 270671 ops)*
* INFO [FlushWriter:47] 2012-08-11 16:38:47,082 Memtable.java (line 266)
Writing Memtable-wordevents@29484922(27340030/74301547 serialized/live
bytes, 270671 ops)*
* INFO [FlushWriter:47] 2012-08-11 16:38:47,990 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-161-Data.db
(14090192 bytes) for commitlog position
ReplayPosition(segmentId=2850431735255183, position=8234095)*
* INFO [CompactionExecutor:96] 2012-08-11 16:38:47,991 CompactionTask.java
(line 109) Compacting
[SSTableReader(path='/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-160-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-159-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-158-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-161-Data.db')]
*
* INFO [CompactionExecutor:96] 2012-08-11 16:38:53,790 CompactionTask.java
(line 221) Compacted to
[/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-162-Data.db,].
 49,579,007 to 49,570,164 (~99% of original) bytes for 20,466 keys at
8.152059MB/s.  Time: 5,799ms.*
* INFO [OptionalTasks:1] 2012-08-11 16:57:39,570 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='OpsCenter',
ColumnFamily='pdps') (estimated 74387670 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 16:57:39,572 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-pdps@5605254(4115229/74387670
serialized/live bytes, 95703 ops)*
* INFO [FlushWriter:48] 2012-08-11 16:57:39,573 Memtable.java (line 266)
Writing Memtable-pdps@5605254(4115229/74387670 serialized/live bytes, 95703
ops)*
* INFO [FlushWriter:48] 2012-08-11 16:57:39,783 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11353-Data.db
(3180163 bytes) for commitlog position
ReplayPosition(segmentId=2850431735255183, position=37579163)*
* INFO [CompactionExecutor:98] 2012-08-11 16:57:39,785 CompactionTask.java
(line 109) Compacting
[SSTableReader(path='/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11353-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11351-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11352-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11350-Data.db')]
*
* INFO [CompactionExecutor:98] 2012-08-11 16:57:41,389 CompactionTask.java
(line 221) Compacted to
[/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11354-Data.db,].
 20,221,486 to 19,712,175 (~97% of original) bytes for 1,707 keys at
11.720072MB/s.  Time: 1,604ms.*
* INFO [MemoryMeter:1] 2012-08-11 17:02:59,319 Memtable.java (line 213)
CFS(Keyspace='CloudPelican', ColumnFamily='events') liveRatio is
3.8540099961262424 (just-counted was 3.6790109706521132).  calculation took
744ms for 97943 columns*
* INFO [OptionalTasks:1] 2012-08-11 17:54:55,132 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='OpsCenter',
ColumnFamily='pdps') (estimated 74327820 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 17:54:55,133 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-pdps@32988119(4111918/74327820
serialized/live bytes, 95626 ops)*
* INFO [FlushWriter:49] 2012-08-11 17:54:55,133 Memtable.java (line 266)
Writing Memtable-pdps@32988119(4111918/74327820 serialized/live bytes,
95626 ops)*
* INFO [FlushWriter:49] 2012-08-11 17:54:55,346 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/OpsCenter/pdps/OpsCenter-pdps-hd-11355-Data.db
(3177704 bytes) for commitlog position
ReplayPosition(segmentId=2850431735255183, position=115958680)*
* INFO [OptionalTasks:1] 2012-08-11 18:03:15,246 MeteredFlusher.java (line
62) flushing high-traffic column family CFS(Keyspace='CloudPelican',
ColumnFamily='wordevents') (estimated 74433332 bytes)*
* INFO [OptionalTasks:1] 2012-08-11 18:03:15,246 ColumnFamilyStore.java
(line 643) Enqueuing flush of Memtable-wordevents@10570291(27388522/74433332
serialized/live bytes, 271607 ops)*
* INFO [FlushWriter:50] 2012-08-11 18:03:15,247 Memtable.java (line 266)
Writing Memtable-wordevents@10570291(27388522/74433332 serialized/live
bytes, 271607 ops)*
* INFO [FlushWriter:50] 2012-08-11 18:03:16,196 Memtable.java (line 307)
Completed flushing
/var/lib/cassandra/data/CloudPelican/wordevents/CloudPelican-wordevents-hd-163-Data.db
(14091793 bytes) for commitlog position
ReplayPosition(segmentId=2850431735255183, position=127624265)*
*ERROR [COMMIT-LOG-ALLOCATOR] 2012-08-11 18:05:45,050
AbstractCassandraDaemon.java (line 134) Exception in thread
Thread[COMMIT-LOG-ALLOCATOR,5,main]*
*java.io.IOError: java.io.IOException: Map failed*
*        at
org.apache.cassandra.db.commitlog.CommitLogSegment.<init>(CommitLogSegment.java:127)
*
*        at
org.apache.cassandra.db.commitlog.CommitLogSegment.freshSegment(CommitLogSegment.java:81)
*
*        at
org.apache.cassandra.db.commitlog.CommitLogAllocator.createFreshSegment(CommitLogAllocator.java:257)
*
*        at
org.apache.cassandra.db.commitlog.CommitLogAllocator.access$500(CommitLogAllocator.java:49)
*
*        at
org.apache.cassandra.db.commitlog.CommitLogAllocator$1.runMayThrow(CommitLogAllocator.java:105)
*
*        at
org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:30)*
*        at java.lang.Thread.run(Unknown Source)*
*Caused by: java.io.IOException: Map failed*
*        at sun.nio.ch.FileChannelImpl.map(Unknown Source)*
*        at
org.apache.cassandra.db.commitlog.CommitLogSegment.<init>(CommitLogSegment.java:119)
*
*        ... 6 more*
*Caused by: java.lang.OutOfMemoryError: Map failed*
*        at sun.nio.ch.FileChannelImpl.map0(Native Method)*
*        ... 8 more*
* INFO [StorageServiceShutdownHook] 2012-08-11 18:05:45,053
CassandraDaemon.java (line 218) Stop listening to thrift clients*
* INFO [StorageServiceShutdownHook] 2012-08-11 18:05:45,054 Gossiper.java
(line 1133) Announcing shutdown*
* INFO [StorageServiceShutdownHook] 2012-08-11 18:05:46,065
MessagingService.java (line 534) Waiting for messaging service to quiesce*
* INFO [ACCEPT-/85.17.231.89] 2012-08-11 18:05:46,066 MessagingService.java
(line 690) MessagingService shutting down server thread.*
*ERROR [Thrift:1532] 2012-08-11 18:05:46,813 CustomTThreadPoolServer.java
(line 204) Error occurred during processing of message.*
*java.util.concurrent.RejectedExecutionException: ThreadPoolExecutor has
shut down*
*        at
org.apache.cassandra.concurrent.DebuggableThreadPoolExecutor$1.rejectedExecution(DebuggableThreadPoolExecutor.java:60)
*
*        at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source)*
*        at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source)*
*        at
org.apache.cassandra.service.StorageProxy.insertLocal(StorageProxy.java:457)
*
*        at
org.apache.cassandra.service.StorageProxy.sendToHintedEndpoints(StorageProxy.java:314)
*
*        at
org.apache.cassandra.service.StorageProxy$2.apply(StorageProxy.java:119)*
*        at
org.apache.cassandra.service.StorageProxy.performWrite(StorageProxy.java:260)
*
*        at
org.apache.cassandra.service.StorageProxy.mutate(StorageProxy.java:193)*
*        at
org.apache.cassandra.thrift.CassandraServer.doInsert(CassandraServer.java:632)
*
*        at
org.apache.cassandra.thrift.CassandraServer.internal_batch_mutate(CassandraServer.java:582)
*
*        at
org.apache.cassandra.thrift.CassandraServer.batch_mutate(CassandraServer.java:590)
*
*        at
org.apache.cassandra.thrift.Cassandra$Processor$batch_mutate.getResult(Cassandra.java:3176)
*
*        at
org.apache.cassandra.thrift.Cassandra$Processor$batch_mutate.getResult(Cassandra.java:3164)
*
*        at
org.apache.thrift.ProcessFunction.process(ProcessFunction.java:32)*
*        at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:34)
*
*        at
org.apache.cassandra.thrift.CustomTThreadPoolServer$WorkerProcess.run(CustomTThreadPoolServer.java:186)
*
*        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown
Source)*
*        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown
Source)*
*        at java.lang.Thread.run(Unknown Source)*


With kind regards,

Robin Verlangen
*Software engineer*
*
*
W http://www.robinverlangen.nl
E robin@us2.nl

Disclaimer: The information contained in this message and attachments is
intended solely for the attention and use of the named addressee and may be
confidential. If you are not the intended recipient, you are reminded that
the information remains the property of the sender. You must not use,
disclose, distribute, copy, print or rely on this e-mail. If you have
received this message in error, please contact the sender immediately and
irrevocably delete this message and any copies.

Mime
View raw message