Today at around 13:50 some cassandra instances experienced shutdown / restarts, all instances recovered on their own but further investigation is needed.
Namely these instances: 1007-b / 1008-b / 1010-b / 1013-c
```lines=4
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log-
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log:ERROR [MessagingService-Incoming-/10.192.48.50] 2016-10-18 13:53:10,337 JVMStabilityInspector.java:117 - JVM state determined to be unstable. Exiting forcefully due to:
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log-java.lang.OutOfMemoryError: Java heap space
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.ByteBuffer.wrap(ByteBuffer.java:373) ~[na:1.8.0_102]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at sun.security.ssl.CipherBox.applyExplicitNonce(CipherBox.java:981) ~[na:1.8.0_102]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at sun.security.ssl.InputRecord.decrypt(InputRecord.java:157) ~[na:1.8.0_102]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1015) ~[na:1.8.0_102]
restbase1007.eqiad.wmnet: --
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.net.MessagingService$SocketThread.run(MessagingService.java:1006) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log:ERROR [SharedPool-Worker-11] 2016-10-18 13:53:10,339 JVMStabilityInspector.java:117 - JVM state determined to be unstable. Exiting forcefully due to:
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log-java.lang.OutOfMemoryError: Java heap space
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57) ~[na:1.8.0_102]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.ByteBuffer.allocate(ByteBuffer.java:335) ~[na:1.8.0_102]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.io.util.RandomAccessReader.readBytes(RandomAccessReader.java:340) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.utils.ByteBufferUtil.read(ByteBufferUtil.java:359) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: --
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.service.StorageService.removeShutdownHook(StorageService.java:748) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log: at org.apache.cassandra.utils.JVMStabilityInspector$Killer.killCurrentJVM(JVMStabilityInspector.java:119) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log: at org.apache.cassandra.utils.JVMStabilityInspector$Killer.killCurrentJVM(JVMStabilityInspector.java:109) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log: at org.apache.cassandra.utils.JVMStabilityInspector.inspectThrowable(JVMStabilityInspector.java:68) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$FutureTask.run(AbstractLocalAwareExecutorService.java:168) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.concurrent.AbstractLocalAwareExecutorService$LocalSessionFutureTask.run(AbstractLocalAwareExecutorService.java:136) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.concurrent.SEPWorker.run(SEPWorker.java:105) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.lang.Thread.run(Thread.java:745) [na:1.8.0_102]
restbase1007.eqiad.wmnet: /var/log/cassandra/system-b.log-INFO [Service Thread] 2016-10-18 13:53:10,343 StatusLogger.java:56 - MigrationStage 0 0 4 0 0
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log-
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log:ERROR [SharedPool-Worker-7] 2016-10-18 13:50:52,452 JVMStabilityInspector.java:117 - JVM state determined to be unstable. Exiting forcefully due to:
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log-java.lang.OutOfMemoryError: Java heap space
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57) ~[na:1.8.0_102]
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.ByteBuffer.allocate(ByteBuffer.java:335) ~[na:1.8.0_102]
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.io.util.RandomAccessReader.readBytes(RandomAccessReader.java:340) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1008.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.utils.ByteBufferUtil.read(ByteBufferUtil.java:359) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log-INFO [Service Thread] 2016-10-18 13:59:25,714 StatusLogger.java:106 - local_group_globaldomain_T_mathoid_check.data 204,10921
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log:ERROR [SharedPool-Worker-9] 2016-10-18 13:59:25,714 JVMStabilityInspector.java:117 - JVM state determined to be unstable. Exiting forcefully due to:
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log-java.lang.OutOfMemoryError: Java heap space
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57) ~[na:1.8.0_102]
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log- at java.nio.ByteBuffer.allocate(ByteBuffer.java:335) ~[na:1.8.0_102]
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.io.util.RandomAccessReader.readBytes(RandomAccessReader.java:340) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1010.eqiad.wmnet: /var/log/cassandra/system-b.log- at org.apache.cassandra.utils.ByteBufferUtil.read(ByteBufferUtil.java:359) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log-INFO [Service Thread] 2016-10-18 13:53:45,570 StatusLogger.java:106 - local_group_wikibooks_T_feed_aggregated.meta 0,0
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log:ERROR [SharedPool-Worker-128] 2016-10-18 13:53:45,570 JVMStabilityInspector.java:117 - JVM state determined to be unstable. Exiting forcefully due to:
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log-java.lang.OutOfMemoryError: Java heap space
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log- at org.apache.cassandra.db.ArrayBackedSortedColumns$CellCollection.iterator(ArrayBackedSortedColumns.java:769) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log- at org.apache.cassandra.db.ColumnFamily.iterator(ColumnFamily.java:488) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log- at org.apache.cassandra.db.ColumnFamily.updateDigest(ColumnFamily.java:396) ~[apache-cassandra-2.2.6.jar:2.2.6]
restbase1013.eqiad.wmnet: /var/log/cassandra/system-c.log- at org.apache.cassandra.db.ColumnFamily.digest(ColumnFamily.java:390) ~[apache-cassandra-2.2.6.jar:2.2.6]
```
== Findings ==
NOTE: The following is a work-in-progress
Looking first at 1007-b, the troubles begin at around 2016-10-18T13:51:05 with a number of tombstone warnings.
```lines=3
WARN [SharedPool-Worker-8] 2016-10-18 13:51:05,403 SliceQueryFilter.java:308 - Read 1 live and 23613 tombstone cells in local_group_default_T_summary.data for key: www.wikidata.org:Q27335792 (see tombstone_warn_threshold). 3 columns were requested, slices=[ea00744c-9539-11e6-b0d3-e8874bd2c097:!-]
WARN [SharedPool-Worker-28] 2016-10-18 13:51:05,477 SliceQueryFilter.java:308 - Read 1 live and 15624 tombstone cells in local_group_default_T_mobileapps_remaining.data for key: www.wikidata.org:Q27335792 (see tombstone_warn_threshold). 1 columns were requested, slices=[-]
WARN [SharedPool-Worker-20] 2016-10-18 13:51:05,766 SliceQueryFilter.java:308 - Read 1 live and 15624 tombstone cells in local_group_default_T_mobileapps_remaining.data for key: www.wikidata.org:Q27335792 (see tombstone_warn_threshold). 1 columns were requested, slices=[-]
WARN [SharedPool-Worker-8] 2016-10-18 13:51:06,438 SliceQueryFilter.java:308 - Read 1 live and 15624 tombstone cells in local_group_default_T_mobileapps_remaining.data for key: www.wikidata.org:Q27335792 (see tombstone_warn_threshold). 3 columns were requested, slices=[ea7f27ba-9539-11e6-88e5-ee03422d6bf0:!-]
WARN [SharedPool-Worker-3] 2016-10-18 13:51:11,059 SliceQueryFilter.java:308 - Read 2 live and 23614 tombstone cells in local_group_default_T_summary.data for key: www.wikidata.org:Q27335792 (see tombstone_warn_threshold). 3 columns were requested, slices=[ed62279d-9539-11e6-9aa0-7acf40f3ba78:!-]
WARN [SharedPool-Worker-31] 2016-10-18 13:51:11,309 SliceQueryFilter.java:308 - Read 2 live and 15628 tombstone cells in local_group_default_T_mobileapps_remaining.data for key: www.wikidata.org:Q27335792 (see tombstone_warn_threshold). 3 columns were requested, slices=[ed6c46a2-9539-11e6-8e21-c9f934dea3db:!-]
```
After which the node entered StatusLogger Hell (an indication that load had become high). As the StatusLogger output progresses, you can see the read stage steadily backing up. At 2016-10-18T13:51:43, a number of read requests fail while fetching a quorum of role permissions from other nodes, and by 2016-10-18T13:53:10 the node OOMed.
```
ERROR [MessagingService-Incoming-/10.192.48.50] 2016-10-18 13:53:10,258 CassandraDaemon.java:185 - Exception in thread Thread[MessagingService-Incoming-/10.192.48.50,5,main]
java.lang.OutOfMemoryError: Java heap space
at java.nio.ByteBuffer.wrap(ByteBuffer.java:373) ~[na:1.8.0_102]
at sun.security.ssl.CipherBox.applyExplicitNonce(CipherBox.java:981) ~[na:1.8.0_102]
at sun.security.ssl.InputRecord.decrypt(InputRecord.java:157) ~[na:1.8.0_102]
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:1015) ~[na:1.8.0_102]
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930) ~[na:1.8.0_102]
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) ~[na:1.8.0_102]
at net.jpountz.lz4.LZ4BlockInputStream.readFully(LZ4BlockInputStream.java:216) ~[lz4-1.3.0.jar:na]
at net.jpountz.lz4.LZ4BlockInputStream.refill(LZ4BlockInputStream.java:150) ~[lz4-1.3.0.jar:na]
at net.jpountz.lz4.LZ4BlockInputStream.read(LZ4BlockInputStream.java:102) ~[lz4-1.3.0.jar:na]
at java.io.DataInputStream.readInt(DataInputStream.java:387) ~[na:1.8.0_102]
at org.apache.cassandra.net.IncomingTcpConnection.receiveMessages(IncomingTcpConnection.java:176) ~[apache-cassandra-2.2.6.jar:2.2.6]
at org.apache.cassandra.net.IncomingTcpConnection.run(IncomingTcpConnection.java:91) ~[apache-cassandra-2.2.6.jar:2.2.6]
```
From the stacktrace, you can see that the OOM occurred while decompressing incoming data off the wire (though this could just be the proverbial camel back-breaking final straw). GC logs could provide additional information, but due to the completely broken way that the JVM rotates out these logs, the subsequent restart obliterated the relevant output.
NOTE: **ACTION:** Open an issue to address the brokeness of JVM GC log rotation (a trivial startup hook would probably suffice).
NOTE: I have not yet done a detailed analysis of the memtable ops/data portion of the StatusLogger output to see if we can glean any insight from specific activity, but from a quick skim, nothing stands out.
=== Heap dumps ===
There is something about Cassandra's handling of OOM exceptions that often times renders the resulting heap dump useless for analysis. You can tell when this occurs, because the heap dump is something less than the size of the heap (12G on these instances). However, it appears that we may have one or more dumps from this event that weren't trampled by the error handler. If intact, these heap dumps would be able to help identify //precisely// where the memory was allocated. Unfortunately, the tools I'm familiar with ([[ https://docs.oracle.com/javase/8/docs/technotes/tools/unix/jvisualvm.html | jvisualvm ]] and [[ http://www.eclipse.org/mat/ | MAT ]]) require a machine with something close to size of the dump in available RAM, and the ability to run a graphical application. I don't presently have access to a desktop machine with this much memory; I'd be grateful to anyone with ideas for how to analyze these.
| restbase1007.eqiad.wmnet | /srv/cassandra-b/java_pid101952.hprof | 12G | Oct 18 13:53 |
| restbase1010.eqiad.wmnet | /srv/cassandra-b/java_pid28339.hprof | 12G | Oct 18 13:59 |
| restbase1011.eqiad.wmnet | /srv/cassandra-a/java_pid11253.hprof | 11G | Oct 15 09:51 |
| restbase1008.eqiad.wmnet | /srv/cassandra-b/java_pid116699.hprof | 8.6G | Oct 18 13:50 |
| restbase1013.eqiad.wmnet | /srv/cassandra-c/java_pid12044.hprof | 12G | Oct 18 13:53 |
NOTE: Prior to closing this issue, these dumps should be cleaned up.