[
https://issues.apache.org/jira/browse/CASSANDRA-9279?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14527378#comment-14527378
]
Brandon Williams edited comment on CASSANDRA-9279 at 5/4/15 9:50 PM:
---------------------------------------------------------------------
Here's another example:
{noformat}
ERROR [COMMIT-LOG-ALLOCATOR] 2015-05-02 04:38:54,102 CommitLog.java (line 420)
Failed to allocate new commit log segments. Commit disk failure policy is stop;
terminating thread
FSWriteError in /var/lib/cassandra/commitlog/CommitLog-3-1430566697635.log
at
org.apache.cassandra.db.commitlog.CommitLogSegment.<init>(CommitLogSegment.java:143)
at
org.apache.cassandra.db.commitlog.CommitLogAllocator$3.run(CommitLogAllocator.java:208)
at
org.apache.cassandra.db.commitlog.CommitLogAllocator$1.runMayThrow(CommitLogAllocator.java:99)
at
org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.FileNotFoundException:
/var/lib/cassandra/commitlog/CommitLog-3-1430566697635.log (Permission denied)
at java.io.RandomAccessFile.open(Native Method)
at java.io.RandomAccessFile.<init>(RandomAccessFile.java:241)
at
org.apache.cassandra.db.commitlog.CommitLogSegment.<init>(CommitLogSegment.java:125)
... 4 more
INFO [CompactionExecutor:4] 2015-05-02 04:38:54,130 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-500-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-501-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-499-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-502-Data.db')]
INFO [CompactionExecutor:12] 2015-05-02 04:38:54,140 ColumnFamilyStore.java
(line 795) Enqueuing flush of
Memtable-compactions_in_progress@1153169288(419/4190 serialized/live bytes, 21
ops)
INFO [FlushWriter:1] 2015-05-02 04:38:54,141 Memtable.java (line 358) Writing
Memtable-compactions_in_progress@1153169288(419/4190 serialized/live bytes, 21
ops)
INFO [CompactionExecutor:25] 2015-05-02 04:38:54,144 ColumnFamilyStore.java
(line 795) Enqueuing flush of
Memtable-compactions_in_progress@1811681988(441/4410 serialized/live bytes, 20
ops)
INFO [FlushWriter:2] 2015-05-02 04:38:54,144 Memtable.java (line 358) Writing
Memtable-compactions_in_progress@1811681988(441/4410 serialized/live bytes, 20
ops)
INFO [FlushWriter:1] 2015-05-02 04:38:54,152 Memtable.java (line 398)
Completed flushing
/var/lib/cassandra/data/system/compactions_in_progress/system-compactions_in_progress-jb-138175-Data.db
(245 bytes) for commitlog position ReplayPosition(segmentId=1430566697633,
position=1621)
INFO [main] 2015-05-02 04:38:54,889 StorageService.java (line 515) Cassandra
version: 2.0.14.352
INFO [main] 2015-05-02 04:38:54,889 StorageService.java (line 516) Thrift API
version: 19.39.0
INFO [main] 2015-05-02 04:38:54,893 StorageService.java (line 517) CQL
supported versions: 2.0.0,3.1.7 (default: 3.1.7)
INFO [main] 2015-05-02 04:38:54,911 StorageService.java (line 540) Loading
persisted ring state
INFO [main] 2015-05-02 04:38:55,404 StorageService.java (line 678) Starting up
server gossip
{noformat}
As you can see, the CLA died, effectively making the machine
useless/problematic, but everything else started up and adversely affected the
cluster. We should instead exit when the CLA dies.
was (Author: brandon.williams):
Here's another example:
{noformat}
ERROR [COMMIT-LOG-ALLOCATOR] 2015-05-02 04:38:54,102 CommitLog.java (line 420)
Failed to allocate new commit log segments. Commit disk failure policy is stop;
terminating thread
FSWriteError in /var/lib/cassandra/commitlog/CommitLog-3-1430566697635.log
at
org.apache.cassandra.db.commitlog.CommitLogSegment.<init>(CommitLogSegment.java:143)
at
org.apache.cassandra.db.commitlog.CommitLogAllocator$3.run(CommitLogAllocator.java:208)
at
org.apache.cassandra.db.commitlog.CommitLogAllocator$1.runMayThrow(CommitLogAllocator.java:99)
at
org.apache.cassandra.utils.WrappedRunnable.run(WrappedRunnable.java:28)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.FileNotFoundException:
/var/lib/cassandra/commitlog/CommitLog-3-1430566697635.log (Permission denied)
at java.io.RandomAccessFile.open(Native Method)
at java.io.RandomAccessFile.<init>(RandomAccessFile.java:241)
at
org.apache.cassandra.db.commitlog.CommitLogSegment.<init>(CommitLogSegment.java:125)
... 4 more
INFO [CompactionExecutor:4] 2015-05-02 04:38:54,130 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-500-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-501-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-499-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/system/sstable_activity/system-sstable_activity-jb-502-Data.db')]
INFO [CompactionExecutor:12] 2015-05-02 04:38:54,140 ColumnFamilyStore.java
(line 795) Enqueuing flush of
Memtable-compactions_in_progress@1153169288(419/4190 serialized/live bytes, 21
ops)
INFO [FlushWriter:1] 2015-05-02 04:38:54,141 Memtable.java (line 358) Writing
Memtable-compactions_in_progress@1153169288(419/4190 serialized/live bytes, 21
ops)
INFO [CompactionExecutor:25] 2015-05-02 04:38:54,144 ColumnFamilyStore.java
(line 795) Enqueuing flush of
Memtable-compactions_in_progress@1811681988(441/4410 serialized/live bytes, 20
ops)
INFO [FlushWriter:2] 2015-05-02 04:38:54,144 Memtable.java (line 358) Writing
Memtable-compactions_in_progress@1811681988(441/4410 serialized/live bytes, 20
ops)
INFO [FlushWriter:1] 2015-05-02 04:38:54,152 Memtable.java (line 398)
Completed flushing
/var/lib/cassandra/data/system/compactions_in_progress/system-compactions_in_progress-jb-138175-Data.db
(245 bytes) for commitlog position ReplayPosition(segmentId=1430566697633,
position=1621)
INFO [CompactionExecutor:12] 2015-05-02 04:38:54,153 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles_indexRecords/UPS_v3_NAM-Profiles_indexRecords-jb-22-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles_indexRecords/UPS_v3_NAM-Profiles_indexRecords-jb-23-Data.db')]
INFO [CompactionExecutor:28] 2015-05-02 04:38:54,153 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles_indexes/UPS_v3_NAM-Profiles_indexes-jb-14-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles_indexes/UPS_v3_NAM-Profiles_indexes-jb-15-Data.db')]
INFO [FlushWriter:2] 2015-05-02 04:38:54,153 Memtable.java (line 398)
Completed flushing
/var/lib/cassandra/data/system/compactions_in_progress/system-compactions_in_progress-jb-138176-Data.db
(221 bytes) for commitlog position ReplayPosition(segmentId=1430566697633,
position=2301)
INFO [CompactionExecutor:20] 2015-05-02 04:38:54,153 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles_indexCache/UPS_v3_NAM-Profiles_indexCache-jb-20-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles_indexCache/UPS_v3_NAM-Profiles_indexCache-jb-19-Data.db')]
INFO [CompactionExecutor:25] 2015-05-02 04:38:54,449 CompactionTask.java (line
120) Compacting
[SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29968-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-30074-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29970-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29969-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29976-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29974-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29977-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29978-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-30077-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-30063-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29967-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29971-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-29972-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-30068-Data.db'),
SSTableReader(path='/var/lib/cassandra/data/UPS_v3_NAM/Profiles/UPS_v3_NAM-Profiles-jb-30062-Data.db')]
INFO [main] 2015-05-02 04:38:54,889 StorageService.java (line 515) Cassandra
version: 2.0.14.352
INFO [main] 2015-05-02 04:38:54,889 StorageService.java (line 516) Thrift API
version: 19.39.0
INFO [main] 2015-05-02 04:38:54,893 StorageService.java (line 517) CQL
supported versions: 2.0.0,3.1.7 (default: 3.1.7)
INFO [main] 2015-05-02 04:38:54,911 StorageService.java (line 540) Loading
persisted ring state
INFO [main] 2015-05-02 04:38:55,404 StorageService.java (line 678) Starting up
server gossip
{noformat}
As you can see, the CLA died, effectively making the machine
useless/problematic, but everything else started up and adversely affected the
cluster. We should instead exit when the CLA dies.
> Gossip (and mutations) lock up on startup
> -----------------------------------------
>
> Key: CASSANDRA-9279
> URL: https://issues.apache.org/jira/browse/CASSANDRA-9279
> Project: Cassandra
> Issue Type: Bug
> Reporter: Sebastian Estevez
> Fix For: 2.0.x
>
> Attachments: Screen Shot 2015-04-30 at 4.41.57 PM.png
>
>
> Cluster running 2.0.14.352 on EC2 - c3.4xl's
> 2 nodes out of 8 exhibited the following behavior
> When starting up the node we noticed it was gray in OpsCenter. Other
> monitoring tool showed it as up.
> Turned out gossip tasks were piling up and we could see the following in the
> system.log:
> {code}
> WARN [GossipTasks:1] 2015-04-30 20:22:29,512 Gossiper.java (line 671) Gossip
> stage has 4270 pending tasks; skipping status check (no nodes will be marked
> down)
> WARN [GossipTasks:1] 2015-04-30 20:22:30,612 Gossiper.java (line 671) Gossip
> stage has 4272 pending tasks; skipping status check (no nodes will be marked
> down)
> WARN [GossipTasks:1] 2015-04-30 20:22:31,713 Gossiper.java (line 671) Gossip
> stage has 4273 pending tasks; skipping status check (no nodes will be marked
> down)
> ...
> {code}
> and tpstats shows blocked tasks--gossip and mutations:
> {code}
> GossipStage 1 3904 29384 0
> 0
> {code}
> the CPU's are inactive (See attachment)
> and dstat output:
> {code}
> You did not select any stats, using -cdngy by default.
> ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
> usr sys idl wai hiq siq| read writ| recv send| in out | int csw
> 2 0 97 0 0 0|1324k 1381k| 0 0 | 0 0 |6252 5548
> 0 0 100 0 0 0| 0 64k| 42k 1017k| 0 0 |3075 2537
> 0 0 99 0 0 0| 0 8192B| 39k 794k| 0 0 |6999 7039
> 0 0 100 0 0 0| 0 0 | 39k 759k| 0 0 |3067 2726
> 0 0 99 0 0 0| 0 184k| 48k 1086k| 0 0 |4829 4178
> 0 0 99 0 0 0| 0 8192B| 34k 802k| 0 0 |1671 1240
> 0 0 100 0 0 0| 0 8192B| 48k 1067k| 0 0 |1878 1193
> {code}
> I managed to grab a thread dump:
> https://gist.githubusercontent.com/anonymous/3b7b4698c32032603493/raw/read.md
> and dmesg:
> https://gist.githubusercontent.com/anonymous/5982b15337c9afbd5d49/raw/f3c2e4411b9d59e90f4615d93c7c1ad25922e170/read.md
> Restarting the node solved the issue (it came up normally), we don't know
> what is causing it but apparently (per the thread dump) gossip threads are
> blocked writing the system keyspace and the writes waiting on the commitlog.
> Gossip:
> {code}
> "GossipStage:1" daemon prio=10 tid=0x00007ffa23471800 nid=0xa13fa waiting on
> condition [0x00007ff9cbe26000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000005d3f50960> (a
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:834)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared(AbstractQueuedSynchronizer.java:964)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1282)
> at
> java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:731)
> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:351)
> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:336)
> at org.apache.cassandra.db.RowMutation.apply(RowMutation.java:211)
> at
> org.apache.cassandra.cql3.statements.ModificationStatement.executeInternal(ModificationStatement.java:709)
> at
> org.apache.cassandra.cql3.QueryProcessor.processInternal(QueryProcessor.java:208)
> at
> org.apache.cassandra.db.SystemKeyspace.updatePeerInfo(SystemKeyspace.java:379)
> - locked <0x00000005d3f41ed8> (a java.lang.Class for
> org.apache.cassandra.db.SystemKeyspace)
> at
> org.apache.cassandra.service.StorageService.updatePeerInfo(StorageService.java:1414)
> at
> org.apache.cassandra.service.StorageService.handleStateNormal(StorageService.java:1524)
> at
> org.apache.cassandra.service.StorageService.onChange(StorageService.java:1350)
> at
> org.apache.cassandra.gms.Gossiper.doOnChangeNotifications(Gossiper.java:1083)
> at org.apache.cassandra.gms.Gossiper.applyNewStates(Gossiper.java:1065)
> at
> org.apache.cassandra.gms.Gossiper.applyStateLocally(Gossiper.java:1023)
> at
> org.apache.cassandra.gms.GossipDigestAckVerbHandler.doVerb(GossipDigestAckVerbHandler.java:58)
> at
> org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:62)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> Locked ownable synchronizers:
> - <0x0000000609517438> (a
> java.util.concurrent.ThreadPoolExecutor$Worker)
> ...
> {code}
> Mutation:
> {code}
> "MutationStage:32" daemon prio=10 tid=0x00007ffa2339c800 nid=0xa1399 waiting
> on condition [0x00007ff9cd6c8000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00000005d486a888> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
> at
> java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:349)
> at
> org.apache.cassandra.db.commitlog.PeriodicCommitLogExecutorService.add(PeriodicCommitLogExecutorService.java:106)
> at org.apache.cassandra.db.commitlog.CommitLog.add(CommitLog.java:206)
> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:357)
> at org.apache.cassandra.db.Keyspace.apply(Keyspace.java:336)
> at org.apache.cassandra.db.RowMutation.apply(RowMutation.java:211)
> at
> org.apache.cassandra.db.RowMutationVerbHandler.doVerb(RowMutationVerbHandler.java:56)
> at
> org.apache.cassandra.net.MessageDeliveryTask.run(MessageDeliveryTask.java:62)
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
> at java.lang.Thread.run(Thread.java:744)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
