cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Jaydeepkumar Chovatia (JIRA)" <j...@apache.org>
Subject [jira] [Updated] (CASSANDRA-13587) Deadlock during CommitLog replay when Cassandra restarts
Date Mon, 12 Jun 2017 23:27:00 GMT

     [ https://issues.apache.org/jira/browse/CASSANDRA-13587?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Jaydeepkumar Chovatia updated CASSANDRA-13587:
----------------------------------------------
    Summary: Deadlock during CommitLog replay when Cassandra restarts  (was: Deadlock during
CommitLog replay when Cassandra restart)

> Deadlock during CommitLog replay when Cassandra restarts
> --------------------------------------------------------
>
>                 Key: CASSANDRA-13587
>                 URL: https://issues.apache.org/jira/browse/CASSANDRA-13587
>             Project: Cassandra
>          Issue Type: Bug
>          Components: Core
>            Reporter: Jaydeepkumar Chovatia
>            Assignee: Jaydeepkumar Chovatia
>             Fix For: 3.0.14
>
>         Attachments: 13587-3.0.txt, Reproduce_CASSANDRA-13587.txt
>
>
> Possible deadlock found when Cassandra is replaying commit log and at the same time Mutation
gets triggered by SSTableReader(SystemKeyspace.persistSSTableReadMeter). As a result Cassandra
restart hangs forever
> Please find details of stack trace here:
> *Frame#1* This thread is trying to apply {{persistSSTableReadMeter}} mutation and as
a result it has called {{writeOrder.start()}} in {{Keyspace.java:533}}
> but there are no Commitlog Segments available because {{createReserveSegments (CommitLogSegmentManager.java)}}
is not yet {{true}} 
> Hence this thread is blocked on {{createReserveSegments}} to become {{true}}, please
note this thread has already started {{writeOrder}}
> {quote}
> "pool-11-thread-1" #251 prio=5 os_prio=0 tid=0x00007fe128478400 nid=0x1b274 waiting on
condition [0x00007fe1389a0000]
>    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:279)
>         at org.apache.cassandra.db.commitlog.CommitLogSegmentManager.advanceAllocatingFrom(CommitLogSegmentManager.java:277)
>         at org.apache.cassandra.db.commitlog.CommitLogSegmentManager.allocate(CommitLogSegmentManager.java:196)
>         at org.apache.cassandra.db.commitlog.CommitLog.add(CommitLog.java:260)
>         at org.apache.cassandra.db.Keyspace.applyInternal(Keyspace.java:540)
>         at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:421)
>         at org.apache.cassandra.db.Mutation.apply(Mutation.java:210)
>         at org.apache.cassandra.db.Mutation.apply(Mutation.java:215)
>         at org.apache.cassandra.db.Mutation.apply(Mutation.java:224)
>         at org.apache.cassandra.cql3.statements.ModificationStatement.executeInternalWithoutCondition(ModificationStatement.java:566)
>         at org.apache.cassandra.cql3.statements.ModificationStatement.executeInternal(ModificationStatement.java:556)
>         at org.apache.cassandra.cql3.QueryProcessor.executeInternal(QueryProcessor.java:295)
>         at org.apache.cassandra.db.SystemKeyspace.persistSSTableReadMeter(SystemKeyspace.java:1181)
>         at org.apache.cassandra.io.sstable.format.SSTableReader$GlobalTidy$1.run(SSTableReader.java:2202)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>         at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
>         at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>         at java.lang.Thread.run(Thread.java:745)
> {quote}
> *Frame#2* This thread is trying to recover commit logs and as a result it tries to flush
Memtable by calling following code:
> {{futures.add(Keyspace.open(SystemKeyspace.NAME).getColumnFamilyStore(SystemKeyspace.BATCHES).forceFlush());}}
> As a result Frame#3 (below) gets created
> {quote}
> "main" #1 prio=5 os_prio=0 tid=0x00007fe1c64ec400 nid=0x1af29 waiting on condition [0x00007fe1c94a1000]
>    java.lang.Thread.State: WAITING (parking)
>         at sun.misc.Unsafe.park(Native Method)
> parking to wait for  <0x00000006370da0c0> (a com.google.common.util.concurrent.ListenableFutureTask)
>         at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>         at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
>         at java.util.concurrent.FutureTask.get(FutureTask.java:191)
>         at org.apache.cassandra.utils.FBUtilities.waitOnFutures(FBUtilities.java:383)
>         at org.apache.cassandra.db.commitlog.CommitLogReplayer.blockForWrites(CommitLogReplayer.java:207)
>         at org.apache.cassandra.db.commitlog.CommitLog.recover(CommitLog.java:182)
>         at org.apache.cassandra.db.commitlog.CommitLog.recover(CommitLog.java:161)
>         at org.apache.cassandra.service.CassandraDaemon.setup(CassandraDaemon.java:295)
>         at org.apache.cassandra.service.CassandraDaemon.activate(CassandraDaemon.java:569)
>         at org.apache.cassandra.service.CassandraDaemon.main(CassandraDaemon.java:697)
> {quote}
> *Frame#3* This thread is waiting at {{writeBarrier.await();}} in {{ColumnFamilyStore.java:1027}}

> but {{writeBarrier}} is locked by thread in Frame#1, and Frame#1 thread is waiting for
more CommitlogSegements to be available. 
> Frame#1 thread will not get new segment because variable {{createReserveSegments(CommitLogSegmentManager.java)}}
is not yet {{true}}. 
> This variable gets set to {{true}} after successful execution of Frame#2.
> Here we can see Frame#3 and Frame#1 are in deadlock state and Cassandra restart hangs
forever.
>  
> {quote}
> "MemtableFlushWriter:5" #433 daemon prio=5 os_prio=0 tid=0x00007e7a4b8b0400 nid=0x1dea8
waiting on condition [0x00007e753c2ca000]
>    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:279)
>         at org.apache.cassandra.utils.concurrent.OpOrder$Barrier.await(OpOrder.java:419)
>         at org.apache.cassandra.db.ColumnFamilyStore$Flush.run(ColumnFamilyStore.java:1027)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>         at org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:79)
>         at org.apache.cassandra.concurrent.NamedThreadFactory$$Lambda$4/1527007086.run(Unknown
Source)
>         at java.lang.Thread.run(Thread.java:745)
> "MemtablePostFlush:3" #432 daemon prio=5 os_prio=0 tid=0x00007e7a4b8b0000 nid=0x1dea7
waiting on condition [0x00007e753c30b000]
>    java.lang.Thread.State: WAITING (parking)
>         at sun.misc.Unsafe.park(Native Method)
>  parking to wait for  <0x00000006370d9cd0> (a java.util.concurrent.CountDownLatch$Sync)
>         at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>         at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>         at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
>         at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
>         at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
>         at org.apache.cassandra.db.ColumnFamilyStore$PostFlush.call(ColumnFamilyStore.java:941)
>         at org.apache.cassandra.db.ColumnFamilyStore$PostFlush.call(ColumnFamilyStore.java:924)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
>         at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
>         at java.util.concurrent.FutureTask.run(FutureTask.java:266)
>         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
>         at org.apache.cassandra.concurrent.NamedThreadFactory.lambda$threadLocalDeallocator$0(NamedThreadFactory.java:79)
>         at org.apache.cassandra.concurrent.NamedThreadFactory$$Lambda$4/1527007086.run(Unknown
Source)
>         at java.lang.Thread.run(Thread.java:745)
> {quote}
> *Reproducible steps*: Reproducing this problem is tricky as it involves multiple conditions
to happen at the same time and is timing bases, so I have done some small code change to reproduce
this:
> 1. Create a Keyspace and table
> 2. Inject data until there are few SSTables generated and CommitLog available
> 3. Kill Cassandra process
> 4. Use the custom code (in the attached file "Reproduce_CASSANDRA-13587.txt") on top
of 3.0.14 branch 
> 5. Build Cassandra jar and use this custom jar
> 6. Restart Cassandra
>     Here you will see Cassandra is hanging forever
> 7. Now apply this fix on top of "Reproduce_CASSANDRA-13587.txt", and repeat step-6
>     Here you should see Cassandra is starting normally
> *Solution*: I am proposing that we should enable variable {{createReserveSegments(CommitLogSegmentManager.java)}}
before recovering any CommitLogs in CommitLog.java file
> so this will not block Frame#1 from acquiring new segment as a result Frame#1 will finish
and then Frame#2 will also finish.
> Please note, this variable {{createReserveSegments}} has been removed from the trunk
branch as part of (https://issues.apache.org/jira/browse/CASSANDRA-10202), also in the trunk
branch CommitLog segments gets created when needed. So as per my understanding enabling this
variable before CommitLog recovery should not create any other side effect, please let me
know your comments.



--
This message was sent by Atlassian JIRA
(v6.4.14#64029)

---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@cassandra.apache.org
For additional commands, e-mail: commits-help@cassandra.apache.org


Mime
View raw message