cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Tyler Hobbs <ty...@datastax.com>
Subject Re: Cassandra OOM crash while mapping commitlog
Date Sat, 11 Aug 2012 20:35:46 GMT
We've seen something similar when running on a 32bit JVM, so make sure
you're using the latest 64bit Java 6 JVM.

On Sat, Aug 11, 2012 at 11:59 AM, Robin Verlangen <robin@us2.nl> wrote:

> 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.
>
>


-- 
Tyler Hobbs
DataStax <http://datastax.com/>

Mime
View raw message