You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Keith Wright <kw...@nanigans.com> on 2014/02/05 15:05:00 UTC
Bootstrap failure
Hi all,
We have been struggling with the inability to bootstrap nodes into our 1.2.13 environment with Vnodes using centos 6.4 with Java 7. We have an 8 node cluster (32 GB RAM, dual hex core, SSDs, 8 GB heap with 1200 MB eden space, RF3) with around 1 TB per node using murmur3. When we go to bootstrap a new node this is what we see:
* Bootstrapping node assigns tokens and requests data from cluster
* 5-6 nodes within the cluster begin to stream data
* Around 2 minutes after bootstrap start, between 1 and 4 nodes (sometimes the bootstrapping node and sometimes not) become unresponsive in par new GCs
* IF no nodes go down during the first 5 minutes of bootstrap, then the bootstrap will succeed without issue
* GC mired nodes tend to recover after a minute or two but the receiving node stops attempting to get more data from the nodes
* Bootstrap eventually fails (after streaming all the data from nodes that did not go down) with Unable to Fetch Ranges
We have tried the following and it appears that sometimes a bootstrap will succeed (perhaps 1 in 10) but with no discernible pattern:
* Increase phi_convict to 16
* Restart all nodes prior to bootstrap (to ensure heap is as “clean” as possible)
* Stop production load against the cluster (to reduce par new churn); after 5 minutes we know if the bootstrap will succeed so we then re-enable load
* Distribute soft interrupts across all CPUs
Below is an output from the GC log of the bootstrapping node when it was stuck in GC.
Has anyone seen this before? This is our production cluster and our inability to grow is a BLOCKING issue for us. Any ideas would be VERY helpful.
Thanks
{Heap before GC invocations=109 (full 0):
par new generation total 1105920K, used 1021140K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 100% used [0x00000005fae00000, 0x0000000636e00000, 0x0000000636e00000)
from space 122880K, 31% used [0x000000063e600000, 0x0000000640b350f0, 0x0000000645e00000)
to space 122880K, 0% used [0x0000000636e00000, 0x0000000636e00000, 0x000000063e600000)
concurrent mark-sweep generation total 7159808K, used 3826815K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 24512K, used 24368K [0x00000007fae00000, 0x00000007fc5f0000, 0x0000000800000000)
2014-02-05T13:27:49.621+0000: 210.242: [GC 210.242: [ParNew: 1021140K->122880K(1105920K), 0.2963210 secs] 4847955K->4024095K(8265728K), 0.2965270 secs] [Times: user=4.97 sys=0.00, real=0.30 secs]
Heap after GC invocations=110 (full 0):
par new generation total 1105920K, used 122880K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 0% used [0x00000005fae00000, 0x00000005fae00000, 0x0000000636e00000)
from space 122880K, 100% used [0x0000000636e00000, 0x000000063e600000, 0x000000063e600000)
to space 122880K, 0% used [0x000000063e600000, 0x000000063e600000, 0x0000000645e00000)
concurrent mark-sweep generation total 7159808K, used 3901215K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 24512K, used 24368K [0x00000007fae00000, 0x00000007fc5f0000, 0x0000000800000000)
}
Total time for which application threads were stopped: 0.2968550 seconds
Application time: 1.5953840 seconds
Total time for which application threads were stopped: 0.0002040 seconds
Application time: 0.0000510 seconds
Re: Bootstrap failure
Posted by Keith Wright <kw...@nanigans.com>.
I did find a stop the world GC on one of the non-bootstrapping nodes during one of our previous bootstrap failures (see below) as well as the flags being passed to the java process. Perhaps this is just a GC tuning issue?
>From what I’ve read, bootstrap is supposed to be a light weight operation. Any idea what Cassandra is doing at this time that would cause such GC pressure? During normal operations, the settings we have now appear to be working fine. Any recommendations on tuning changes?
/usr/java/default/bin/java -ea -javaagent:/usr/local/cassandra/lib/jamm-0.2.5.jar -XX:+UseThreadPriorities -XX:ThreadPriorityPolicy=42 -Xms8G -Xmx8G -Xmn1200M -XX:+HeapDumpOnOutOfMemoryError -Xss256k -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+CMSParallelRemarkEnabled -XX:SurvivorRatio=8 -XX:MaxTenuringThreshold=1 -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -XX:+UseCompressedOops -XX:+UseTLAB -XX:+UseCondCardMark -XX:-UseBiasedLocking -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -Xloggc:/var/log/cassandra/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=10M -Djava.net.preferIPv4Stack=true -Dcom.sun.management.jmxremote.port=7199 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false -Djava.util.logging.config.file=/usr/local/cassandra/conf/logging.properties -javaagent:/usr/local/cassandra/lib/jmxetric-1.0.4.jar=host=lxpcas001.nanigans.com,port=8649,wireformat31x=true,config=/usr/local/cassandra/conf/jmxetric.xml -Dlog4j.configuration=log4j-server.properties -Dlog4j.defaultInitOverride=true -Dcassandra-foreground=yes -cp /usr/local/cassandra/conf:/usr/local/cassandra/build/classes/main:/usr/local/cassandra/build/classes/thrift:/usr/local/cassandra/lib/antlr-3.2.jar:/usr/local/cassandra/lib/apache-cassandra-1.2.12.jar:/usr/local/cassandra/lib/apache-cassandra-clientutil-1.2.12.jar:/usr/local/cassandra/lib/apache-cassandra-thrift-1.2.12.jar:/usr/local/cassandra/lib/avro-1.4.0-fixes.jar:/usr/local/cassandra/lib/avro-1.4.0-sources-fixes.jar:/usr/local/cassandra/lib/commons-cli-1.1.jar:/usr/local/cassandra/lib/commons-codec-1.2.jar:/usr/local/cassandra/lib/commons-lang-2.6.jar:/usr/local/cassandra/lib/compress-lzf-0.8.4.jar:/usr/local/cassandra/lib/concurrentlinkedhashmap-lru-1.3.jar:/usr/local/cassandra/lib/gmetric4j-1.0.3.jar:/usr/local/cassandra/lib/guava-13.0.1.jar:/usr/local/cassandra/lib/high-scale-lib-1.1.2.jar:/usr/local/cassandra/lib/jackson-core-asl-1.9.2.jar:/usr/local/cassandra/lib/jackson-mapper-asl-1.9.2.jar:/usr/local/cassandra/lib/jamm-0.2.5.jar:/usr/local/cassandra/lib/jbcrypt-0.3m.jar:/usr/local/cassandra/lib/jline-1.0.jar:/usr/local/cassandra/lib/jmxetric-1.0.4.jar:/usr/local/cassandra/lib/jna.jar:/usr/local/cassandra/lib/json-simple-1.1.jar:/usr/local/cassandra/lib/libthrift-0.7.0.jar:/usr/local/cassandra/lib/log4j-1.2.16.jar:/usr/local/cassandra/lib/lz4-1.1.0.jar:/usr/local/cassandra/lib/metrics-core-2.2.0.jar:/usr/local/cassandra/lib/netty-3.6.6.Final.jar:/usr/local/cassandra/lib/oncrpc-1.0.7.jar:/usr/local/cassandra/lib/servlet-api-2.5-20081211.jar:/usr/local/cassandra/lib/slf4j-api-1.7.2.jar:/usr/local/cassandra/lib/slf4j-log4j12-1.7.2.jar:/usr/local/cassandra/lib/snakeyaml-1.6.jar:/usr/local/cassandra/lib/snappy-java-1.0.5.jar:/usr/local/cassandra/lib/snaptree-0.1.jar org.apache.cassandra.service.CassandraDaemon
{Heap before GC invocations=518 (full 1):
par new generation total 1105920K, used 17921K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 1% used [0x00000005fae00000, 0x00000005fbf29db8, 0x0000000636e00000)
from space 122880K, 0% used [0x0000000636e00000, 0x0000000636e56938, 0x000000063e600000)
to space 122880K, 0% used [0x000000063e600000, 0x000000063e600000, 0x0000000645e00000)
concurrent mark-sweep generation total 7159808K, used 6367511K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 29888K, used 29784K [0x00000007fae00000, 0x00000007fcb30000, 0x0000000800000000)
2014-02-04T16:16:44.471+0000: 945.646: [GC 945.646: [ParNew: 17921K->364K(1105920K), 0.0090810 secs]945.655: [CMS2014-02-04T16:16:48.373+0000: 949.548: [CMS-concurrent-sweep: 3.938/4.362 secs] [Times: user=9.10 sys=0.19, real=4.36 secs]
(concurrent mode failure): 6367540K->4453666K(7159808K), 16.4971830 secs] 6385433K->4453666K(8265728K), [CMS Perm : 29784K->29740K(29888K)], 16.5083610 secs] [Times: user=16.61 sys=0.00, real=16.50 secs]
Heap after GC invocations=519 (full 2):
par new generation total 1105920K, used 0K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 0% used [0x00000005fae00000, 0x00000005fae00000, 0x0000000636e00000)
from space 122880K, 0% used [0x000000063e600000, 0x000000063e600000, 0x0000000645e00000)
to space 122880K, 0% used [0x0000000636e00000, 0x0000000636e00000, 0x000000063e600000)
concurrent mark-sweep generation total 7159808K, used 4453666K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 49568K, used 29740K [0x00000007fae00000, 0x00000007fde68000, 0x0000000800000000)
}
Total time for which application threads were stopped: 16.5111290 seconds
Application time: 0.0094340 seconds
Total time for which application threads were stopped: 0.2300320 seconds
Application time: 0.0000550 seconds
2014-02-04T16:17:01.221+0000: 962.396: [GC [1 CMS-initial-mark: 5584142K(7159808K)] 5614460K(8265728K), 0.0240930 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
Total time for which application threads were stopped: 0.0259820 seconds
2014-02-04T16:17:01.246+0000: 962.420: [CMS-concurrent-mark-start]
Application time: 0.6072530 seconds
{Heap before GC invocations=519 (full 3):
par new generation total 1105920K, used 983040K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 100% used [0x00000005fae00000, 0x0000000636e00000, 0x0000000636e00000)
from space 122880K, 0% used [0x000000063e600000, 0x000000063e600000, 0x0000000645e00000)
to space 122880K, 0% used [0x0000000636e00000, 0x0000000636e00000, 0x000000063e600000)
concurrent mark-sweep generation total 7159808K, used 5584142K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 49568K, used 29776K [0x00000007fae00000, 0x00000007fde68000, 0x0000000800000000)
2014-02-04T16:17:01.855+0000: 963.030: [GC 963.030: [ParNew: 983040K->21724K(1105920K), 0.0249840 secs] 6567182K->5605866K(8265728K), 0.0254720 secs] [Times: user=0.42 sys=0.00, real=0.02 secs]
Heap after GC invocations=520 (full 3):
par new generation total 1105920K, used 21724K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 0% used [0x00000005fae00000, 0x00000005fae00000, 0x0000000636e00000)
from space 122880K, 17% used [0x0000000636e00000, 0x0000000638337290, 0x000000063e600000)
to space 122880K, 0% used [0x000000063e600000, 0x000000063e600000, 0x0000000645e00000)
concurrent mark-sweep generation total 7159808K, used 5584142K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 49568K, used 29776K [0x00000007fae00000, 0x00000007fde68000, 0x0000000800000000)
}
Total time for which application threads were stopped: 0.0280980 seconds
Application time: 0.5525030 seconds
Total time for which application threads were stopped: 0.0547220 seconds
Application time: 0.0009410 seconds
{Heap before GC invocations=520 (full 3):
From: Keith Wright <kw...@nanigans.com>>
Reply-To: "user@cassandra.apache.org<ma...@cassandra.apache.org>" <us...@cassandra.apache.org>>
Date: Wednesday, February 5, 2014 at 9:05 AM
To: "user@cassandra.apache.org<ma...@cassandra.apache.org>" <us...@cassandra.apache.org>>
Cc: Don Jackson <dj...@nanigans.com>>, Dave Carroll <dc...@nanigans.com>>
Subject: Bootstrap failure
Hi all,
We have been struggling with the inability to bootstrap nodes into our 1.2.13 environment with Vnodes using centos 6.4 with Java 7. We have an 8 node cluster (32 GB RAM, dual hex core, SSDs, 8 GB heap with 1200 MB eden space, RF3) with around 1 TB per node using murmur3. When we go to bootstrap a new node this is what we see:
* Bootstrapping node assigns tokens and requests data from cluster
* 5-6 nodes within the cluster begin to stream data
* Around 2 minutes after bootstrap start, between 1 and 4 nodes (sometimes the bootstrapping node and sometimes not) become unresponsive in par new GCs
* IF no nodes go down during the first 5 minutes of bootstrap, then the bootstrap will succeed without issue
* GC mired nodes tend to recover after a minute or two but the receiving node stops attempting to get more data from the nodes
* Bootstrap eventually fails (after streaming all the data from nodes that did not go down) with Unable to Fetch Ranges
We have tried the following and it appears that sometimes a bootstrap will succeed (perhaps 1 in 10) but with no discernible pattern:
* Increase phi_convict to 16
* Restart all nodes prior to bootstrap (to ensure heap is as “clean” as possible)
* Stop production load against the cluster (to reduce par new churn); after 5 minutes we know if the bootstrap will succeed so we then re-enable load
* Distribute soft interrupts across all CPUs
Below is an output from the GC log of the bootstrapping node when it was stuck in GC.
Has anyone seen this before? This is our production cluster and our inability to grow is a BLOCKING issue for us. Any ideas would be VERY helpful.
Thanks
{Heap before GC invocations=109 (full 0):
par new generation total 1105920K, used 1021140K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 100% used [0x00000005fae00000, 0x0000000636e00000, 0x0000000636e00000)
from space 122880K, 31% used [0x000000063e600000, 0x0000000640b350f0, 0x0000000645e00000)
to space 122880K, 0% used [0x0000000636e00000, 0x0000000636e00000, 0x000000063e600000)
concurrent mark-sweep generation total 7159808K, used 3826815K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 24512K, used 24368K [0x00000007fae00000, 0x00000007fc5f0000, 0x0000000800000000)
2014-02-05T13:27:49.621+0000: 210.242: [GC 210.242: [ParNew: 1021140K->122880K(1105920K), 0.2963210 secs] 4847955K->4024095K(8265728K), 0.2965270 secs] [Times: user=4.97 sys=0.00, real=0.30 secs]
Heap after GC invocations=110 (full 0):
par new generation total 1105920K, used 122880K [0x00000005fae00000, 0x0000000645e00000, 0x0000000645e00000)
eden space 983040K, 0% used [0x00000005fae00000, 0x00000005fae00000, 0x0000000636e00000)
from space 122880K, 100% used [0x0000000636e00000, 0x000000063e600000, 0x000000063e600000)
to space 122880K, 0% used [0x000000063e600000, 0x000000063e600000, 0x0000000645e00000)
concurrent mark-sweep generation total 7159808K, used 3901215K [0x0000000645e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 24512K, used 24368K [0x00000007fae00000, 0x00000007fc5f0000, 0x0000000800000000)
}
Total time for which application threads were stopped: 0.2968550 seconds
Application time: 1.5953840 seconds
Total time for which application threads were stopped: 0.0002040 seconds
Application time: 0.0000510 seconds