<= br>

On Wed, Jan 8, 2014 at 7:15 AM, Desimpel, Ignace= <Ignace.Desimpel@nuance.com> wrote:

Hi,

=A0

On linux and cassandra version 2.0.2 I had an OOM af= ter a heavy load and then some (15 ) days of idle running (not exactly idle= but very very low activity).

Two out of a 4 machine cluster had this OOM.<= u>

=A0

I checked the heap dump (9GB) and that tells me :=

=A0

One instance of "java.util.concurrent.ScheduledThreadPoolExecutor" loaded = by "<system class loader>" occupies 8.927.175.368 (94,53%) bytes. The instance is referenced by org.a= pache.cassandra.io.sstable.SSTableReader @ 0x7fadf89e0=A0, loaded by "sun.misc.Launcher$AppClassLoader @ 0x683e6ad30". The memo= ry is accumulated in one instance of "java.util.concurrent.RunnableScheduledFuture[]" loaded by= "<system class loader>".

=A0

So I checked the SSTableReader instance and found ou= t the =91ScheduledThreadPoolExecutor syncExecutor =91 object is holding abo= ut 600k of ScheduledFutureTasks.

According to the code on SSTableReader these tasks m= ust have been created by the code line syncExecutor.scheduleAtFixedRate. Th= at means that none of these tasks ever get scheduled because some (and only= one) initial task is probably blocking.

But then again, the one thread to execute these task= s, seems to be in a =91normal=92 state (at time of OOM) and is executing wi= th a stack trace pasted below :

=A0

Thread 0x696777eb8

=A0 at org.apache.cassandra.db.AtomicSortedColumns$1= .create(Lorg/apache/cassandra/config/CFMetaData;Z)Lorg/apache/cassandra/db/= AtomicSortedColumns; (AtomicSortedColumns.java:58)

=A0 at org.apache.cassandra.db.AtomicSortedColumns$1= .create(Lorg/apache/cassandra/config/CFMetaData;Z)Lorg/apache/cassandra/db/= ColumnFamily; (AtomicSortedColumns.java:55)

=A0 at org.apache.cassandra.db.ColumnFamily.cloneMeS= hallow(Lorg/apache/cassandra/db/ColumnFamily$Factory;Z)Lorg/apache/cassandr= a/db/ColumnFamily; (ColumnFamily.java:70)

=A0 at org.apache.cassandra.db.Memtable.resolve(Lorg= /apache/cassandra/db/DecoratedKey;Lorg/apache/cassandra/db/ColumnFamily;Lor= g/apache/cassandra/db/index/SecondaryIndexManager$Updater;)V (Memtable.java= :187)

=A0 at org.apache.cassandra.db.Memtable.put(Lorg/apa= che/cassandra/db/DecoratedKey;Lorg/apache/cassandra/db/ColumnFamily;Lorg/ap= ache/cassandra/db/index/SecondaryIndexManager$Updater;)V (Memtable.java:158= )

=A0 at org.apache.cassandra.db.ColumnFamilyStore.app= ly(Lorg/apache/cassandra/db/DecoratedKey;Lorg/apache/cassandra/db/ColumnFam= ily;Lorg/apache/cassandra/db/index/SecondaryIndexManager$Updater;)V (Column= FamilyStore.java:840)

=A0 at org.apache.cassandra.db.Keyspace.apply(Lorg/a= pache/cassandra/db/RowMutation;ZZ)V (Keyspace.java:373)

=A0 at org.apache.cassandra.db.Keyspace.apply(Lorg/a= pache/cassandra/db/RowMutation;Z)V (Keyspace.java:338)

=A0 at org.apache.cassandra.db.RowMutation.apply()V = (RowMutation.java:201)

=A0 at org.apache.cassandra.cql3.statements.Modifica= tionStatement.executeInternal(Lorg/apache/cassandra/service/QueryState;)Lor= g/apache/cassandra/transport/messages/ResultMessage; (ModificationStatement= .java:477)

=A0 at org.apache.cassandra.cql3.QueryProcessor.proc= essInternal(Ljava/lang/String;)Lorg/apache/cassandra/cql3/UntypedResultSet;= (QueryProcessor.java:178)

=A0 at org.apache.cassandra.db.SystemKeyspace.persis= tSSTableReadMeter(Ljava/lang/String;Ljava/lang/String;ILorg/apache/cassandr= a/metrics/RestorableMeter;)V (SystemKeyspace.java:938)

=A0 at org.apache.cassandra.io.sstable.SSTableReader= $2.run()V (SSTableReader.java:342)

=A0 at java.util.concurrent.Executors$RunnableAdapte= r.call()Ljava/lang/Object; (Executors.java:471)

=A0 at java.util.concurrent.FutureTask.runAndReset()= Z (FutureTask.java:304)

=A0 at java.util.concurrent.ScheduledThreadPoolExecu= tor$ScheduledFutureTask.access$301(Ljava/util/concurrent/ScheduledThreadPoo= lExecutor$ScheduledFutureTask;)Z (ScheduledThreadPoolExecutor.java:178)<= /u>

=A0 at java.util.concurrent.ScheduledThreadPoolExecu= tor$ScheduledFutureTask.run()V (ScheduledThreadPoolExecutor.java:293)

=A0 at java.util.concurrent.ThreadPoolExecutor.runWo= rker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V (ThreadPoolExecutor= .java:1145)

=A0 at java.util.concurrent.ThreadPoolExecutor$Worke= r.run()V (ThreadPoolExecutor.java:615)

=A0 at java.lang.Thread.run()V (Thread.java:724)<= /u>

=A0

Since each of these tasks are throttled by meterSync= Throttle.acquire() I suspect that the RateLimiter is causing a delay. The R= ateLimiter instance attributes are :

Type|Name=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0=A0= =A0 |Value

long|nextFreeTicketMicros|3016022567383

double|maxPermits|100.0

double|storedPermits|99.0

long|offsetNanos|334676357831746

=A0

I guess that these attributes will practically resul= t in a blocking behavior, resulting in the OOM =85

=A0

Is there someone that can make sense out of it?

I hope this helps in finding out what the reason is = for this and maybe could be avoided in the future. I still have the heap du= mp, so I can always pass more information if needed.

=A0

Regards,

=A0

Ignace Desimpel

--
Tyler Hobbs
DataStax