cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Robin Verlangen <ro...@us2.nl>
Subject Re: Cassandra OOM crash while mapping commitlog
Date Sun, 12 Aug 2012 11:36:42 GMT
Hmm, is issue caused by some 1.x version? Before it never occurred to us.
Op 11 aug. 2012 22:36 schreef "Tyler Hobbs" <tyler@datastax.com> het
volgende:

> 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