You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cassandra.apache.org by "Jonathan Ellis (JIRA)" <ji...@apache.org> on 2014/02/06 01:04:11 UTC
[jira] [Updated] (CASSANDRA-6653) Attempting to bootstrap causes
nodes to lock up in GC
[ https://issues.apache.org/jira/browse/CASSANDRA-6653?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Jonathan Ellis updated CASSANDRA-6653:
--------------------------------------
Description:
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.
{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
Relevant portion of GC log from non-bootstrapping node:
{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):
Java flags:
/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
was:
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.
This is our production cluster and our inability to grow is a BLOCKING issue for us. Any ideas would be VERY helpful.
Thanks
Relevant portion of GC log from bootstrapping node:
{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
Relevant portion of GC log from non-bootstrapping node:
{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):
Java flags:
/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
> Attempting to bootstrap causes nodes to lock up in GC
> -----------------------------------------------------
>
> Key: CASSANDRA-6653
> URL: https://issues.apache.org/jira/browse/CASSANDRA-6653
> Project: Cassandra
> Issue Type: Bug
> Components: Core
> Environment: VNodes using Murmur3
> Reporter: Keith Wright
>
> 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.
> {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
> Relevant portion of GC log from non-bootstrapping node:
> {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):
> Java flags:
> /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
--
This message was sent by Atlassian JIRA
(v6.1.5#6160)