You are viewing a plain text version of this content. The canonical link for it is here.

Posted to user@cassandra.apache.org by Jeff Ferland <jb...@tubularlabs.com> on 2015/11/02 19:55:27 UTC

Re: Cassandra stalls and dropped messages not due to GC

Having caught a node in an undesirable state, many of my threads are reading like this:
"SharedPool-Worker-5" #875 daemon prio=5 os_prio=0 tid=0x00007f3e14196800 nid=0x96ce waiting on condition [0x00007f3ddb835000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:304)
        at org.apache.cassandra.utils.concurrent.WaitQueue$AbstractSignal.awaitUninterruptibly(WaitQueue.java:283)
        at org.apache.cassandra.db.commitlog.PeriodicCommitLogService.maybeWaitForSync(PeriodicCommitLogService.java:44)
        at org.apache.cassandra.db.commitlog.AbstractCommitLogService.finishWriteFor(AbstractCommitLogService.java:152)
        at org.apache.cassandra.db.commitlog.CommitLog.add(CommitLog.java:252)
        at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:379)
        at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:359)
        at org.apache.cassandra.db.Mutation.apply(Mutation.java:214)
        at org.apache.cassandra.db.MutationVerbHandler.doVerb(MutationVerbHandler.java:54)
        at org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:64)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
        at org.apache.cassandra.concurrent.AbstractTracingAwareExecutorService$FutureTask.run(AbstractTracingAwareExecutorService.java:164)
        at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:105)
        at java.lang.Thread.run(Thread.java:745)

But commit log loading seems evenly spaced and low enough in volume:
/mnt/cassandra/commitlog$ ls -lht | head
total 7.2G
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:50 CommitLog-4-1446162051324.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:50 CommitLog-4-1446162051323.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:50 CommitLog-4-1446162051322.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:49 CommitLog-4-1446162051321.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:49 CommitLog-4-1446162051320.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:48 CommitLog-4-1446162051319.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:48 CommitLog-4-1446162051318.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:47 CommitLog-4-1446162051317.log
-rw-r--r-- 1 cassandra cassandra 32M Nov  2 18:46 CommitLog-4-1446162051316.log

Commit logs are on 10 second periodic setting:
commitlog_sync: periodic
commitlog_sync_period_in_ms: 10000

SSDs are fully trimmed out and mounted with discard since it snuck into my head that could be an issue. Still stuck diagnosing this.

> On Oct 30, 2015, at 3:37 PM, Nate McCall <na...@thelastpickle.com> wrote:
> 
> Does tpstats show unusually high counts for blocked flush writers? 

The “All Time Blocked” metric is 0 across my entire cluster.

> As Sebastian suggests, running ttop will paint a clearer picture about what is happening within C*. I would however recommend going back to CMS in this case as that is the devil we all know and more folks will be able to offer advice on seeing its output (and it removes a delta). 

Forgive me, but what is CMS?

> 
> It’s starting to look to me like it’s possibly related to brief IO spikes that are smaller than my usual graphing granularity. It feels surprising to me that these would affect the Gossip threads, but it’s the best current lead I have with my debugging right now. More to come when I learn it.
> 
> Probably not the case since this was a result of an upgrade, but I've seen similar behavior on systems where some kernels had issues with irqbalance doing the right thing and would end up parking most interrupts on CPU0 (like say for the disk and ethernet modules) regardless of the number of cores. Check out proc via 'cat /proc/interrupts' and make sure the interrupts are spread out of CPU cores. You can steer them off manually at runtime if they are not spread out. 

Interrupt loading is even.

> Also, did you upgrade anything besides Cassandra?

No. I’ve tried some mitigations since tuning thread pool sizes and GC, but the problem begins with only an upgrade of Cassandra. No other system packages, kernels, etc.

-Jeff

Re: Cassandra stalls and dropped messages not due to GC

Posted by Jeff Ferland <jb...@tubularlabs.com>.

> On Nov 2, 2015, at 11:35 AM, Nate McCall <na...@thelastpickle.com> wrote:
> Forgive me, but what is CMS?
> 
> Sorry - ConcurrentMarkSweep garbage collector. 

Ah, my brain was trying to think in terms of something Cassandra specific. I have full GC logging on and since moving to G1, I haven’t had any >500ms GC cycles and the >200ms logger triggers about once every 2 minutes. I don’t intend to roll off that given positive confirmation that the cycles seem to be working well and GC logs don’t line up with outages. Also, the issue proved to be the same on CMS as on G1.

> 
> No. I’ve tried some mitigations since tuning thread pool sizes and GC, but the problem begins with only an upgrade of Cassandra. No other system packages, kernels, etc.
> 
> 
> 
> From what 2.0 version did you upgrade? If it was < 2.0.7, you would need to run 'nodetool upgradesstables'  but I'm not sure the issue would manifest that way. Otherwise, double check the DSE release notes and upgrade guide. I've not had any issues like this going from 2.0.x to 2.1.x on vanilla C*. 

2.0.14 or higher. I don’t recall what version of DSE I standardized on last, but probably 2.0.16. In any case, the format moved from jb to ka.

I checked into the related source code and from there gripped my logs where I’m seeing messages like (most extreme example):

WARN  [PERIODIC-COMMIT-LOG-SYNCER] 2015-11-02 23:10:16,478  AbstractCommitLogService.java:105 - Out of 38 commit log syncs over the past 307s with average duration of 2087.32ms, 3 have exceeded the configured commit interval by an average of 15515.67ms

I seem to have 3-4 32MB commit logs created per minute. In a quick experiment, I’ve run nodetool flush just now and reduced a 5.7G directory to 58M. I’m going to flush all the nodes and see if that’s somehow related where it’s just holding commit logs too long. (Did I miss the configuration for maximum memtable age?)

-Jeff

Re: Cassandra stalls and dropped messages not due to GC

Posted by Nate McCall <na...@thelastpickle.com>.

>
>
> Forgive me, but what is CMS?
>

Sorry - ConcurrentMarkSweep garbage collector.


>
> No. I’ve tried some mitigations since tuning thread pool sizes and GC, but
> the problem begins with only an upgrade of Cassandra. No other system
> packages, kernels, etc.
>
>
>
>From what 2.0 version did you upgrade? If it was < 2.0.7, you would need to
run 'nodetool upgradesstables'  but I'm not sure the issue would manifest
that way. Otherwise, double check the DSE release notes and upgrade guide.
I've not had any issues like this going from 2.0.x to 2.1.x on vanilla C*.



-- 
-----------------
Nate McCall
Austin, TX
@zznate

Co-Founder & Sr. Technical Consultant
Apache Cassandra Consulting
http://www.thelastpickle.com