[jira] [Updated] (CASSANDRA-5360) Disable Thread Biased Locking in the JVM
[
https://issues.apache.org/jira/browse/CASSANDRA-5360?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ryan McGuire updated CASSANDRA-5360:
Labels: qa-resolved (was: )
Disable Thread Biased Locking in the JVM
Key: CASSANDRA-5360
URL: https://issues.apache.org/jira/browse/CASSANDRA-5360
Project: Cassandra
Issue Type: Improvement
Components: Core
Affects Versions: 1.0.12, 1.1.10, 1.2.3
Reporter: amorton
Assignee: amorton
Priority: Minor
Labels: qa-resolved
Attachments: 5360.txt, cassandra-biased-locking-tests.txt
Biased Locking
(https://blogs.oracle.com/dave/entry/biased_locking_in_hotspot) is enabled by
default in JVM 6 and is designed to optimise applications where a locks are
normally used by one thread. This is the opposite of how the worker pools
cassandra work. Disabling Biased Locking (-XX:-UseBiasedLocking) has yielded
improvements of 5% to 10% in throughput and reduced JVM pauses.
Details follow.
h1. Application Pausing
The following was observed on a 16 core EC2 SSD instance...
{noformat}
Heap after GC invocations=32 (full 0):
par new generation total 1024000K, used 59799K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 0% used [0x0006fae0, 0x0006fae0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22592K, used 22578K
[0x0007fae0, 0x0007fc41, 0x0008)
}
Total time for which application threads were stopped: 0.0175680 seconds
Total time for which application threads were stopped: 0.0008680 seconds
Total time for which application threads were stopped: 0.0004030 seconds
Total time for which application threads were stopped: 0.0006460 seconds
Total time for which application threads were stopped: 0.0009210 seconds
Total time for which application threads were stopped: 0.0007250 seconds
Total time for which application threads were stopped: 0.0016340 seconds
Total time for which application threads were stopped: 0.0005570 seconds
Total time for which application threads were stopped: 0.0007270 seconds
Total time for which application threads were stopped: 0.0010170 seconds
Total time for which application threads were stopped: 0.0006240 seconds
Total time for which application threads were stopped: 0.0013250 seconds
{Heap before GC invocations=32 (full 0):
par new generation total 1024000K, used 878999K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 100% used [0x0006fae0, 0x00072ce0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22784K, used 22591K
[0x0007fae0, 0x0007fc44, 0x0008)
2013-03-15T21:21:17.015+: 1038.849: [GC Before GC:
Statistics for BinaryTreeDictionary:
{noformat}
The extra were stopped lines were annoying me, and the JVM Performance book
offered this explanation:
bq. If there happens to be additional safepoints between garbage collections,
the output will show Application time: and Total time for which application
threads were stopped: messages for each safepoint that occurs between garbage
collections.
h1. Safepoints
Safepoints are times when the JVM pauses all application threads to run a
single VM thread that needs to know the heap is not going to change. GC is
one cause, others are (from Java Performance):
bq. There many other safepoints, such as biased locking revocation, thread
stack dumps, thread suspension or stopping (i.e., java.lang.Thread.stop()
method), and numerous inspection and modification operations requested
through JVMTI.
On my MBP (corei7, 16Gb, ssd) I ran cassandra with the stress test with
-XX:-PrintGCApplicationConcurrentTime and -XX:-PrintSafepointStatistics which
outputs information when the JVM exits. The biased-locking-tests.txt
attachment shows that stress took 1m 23 seconds to complete and the
safepoint statistics show most of the pauses were to revoke biased locks.
A second test was run (both with a clean data dir) with biased locking
disabled that took 1 minute 18 seconds. The safepoint stats did not
[jira] [Updated] (CASSANDRA-5360) Disable Thread Biased Locking in the JVM
[
https://issues.apache.org/jira/browse/CASSANDRA-5360?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Ryan McGuire updated CASSANDRA-5360:
Tester: enigmacurry
Disable Thread Biased Locking in the JVM
Key: CASSANDRA-5360
URL: https://issues.apache.org/jira/browse/CASSANDRA-5360
Project: Cassandra
Issue Type: Improvement
Components: Core
Affects Versions: 1.0.12, 1.1.10, 1.2.3
Reporter: amorton
Assignee: amorton
Priority: Minor
Attachments: 5360.txt, cassandra-biased-locking-tests.txt
Biased Locking
(https://blogs.oracle.com/dave/entry/biased_locking_in_hotspot) is enabled by
default in JVM 6 and is designed to optimise applications where a locks are
normally used by one thread. This is the opposite of how the worker pools
cassandra work. Disabling Biased Locking (-XX:-UseBiasedLocking) has yielded
improvements of 5% to 10% in throughput and reduced JVM pauses.
Details follow.
h1. Application Pausing
The following was observed on a 16 core EC2 SSD instance...
{noformat}
Heap after GC invocations=32 (full 0):
par new generation total 1024000K, used 59799K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 0% used [0x0006fae0, 0x0006fae0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22592K, used 22578K
[0x0007fae0, 0x0007fc41, 0x0008)
}
Total time for which application threads were stopped: 0.0175680 seconds
Total time for which application threads were stopped: 0.0008680 seconds
Total time for which application threads were stopped: 0.0004030 seconds
Total time for which application threads were stopped: 0.0006460 seconds
Total time for which application threads were stopped: 0.0009210 seconds
Total time for which application threads were stopped: 0.0007250 seconds
Total time for which application threads were stopped: 0.0016340 seconds
Total time for which application threads were stopped: 0.0005570 seconds
Total time for which application threads were stopped: 0.0007270 seconds
Total time for which application threads were stopped: 0.0010170 seconds
Total time for which application threads were stopped: 0.0006240 seconds
Total time for which application threads were stopped: 0.0013250 seconds
{Heap before GC invocations=32 (full 0):
par new generation total 1024000K, used 878999K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 100% used [0x0006fae0, 0x00072ce0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22784K, used 22591K
[0x0007fae0, 0x0007fc44, 0x0008)
2013-03-15T21:21:17.015+: 1038.849: [GC Before GC:
Statistics for BinaryTreeDictionary:
{noformat}
The extra were stopped lines were annoying me, and the JVM Performance book
offered this explanation:
bq. If there happens to be additional safepoints between garbage collections,
the output will show Application time: and Total time for which application
threads were stopped: messages for each safepoint that occurs between garbage
collections.
h1. Safepoints
Safepoints are times when the JVM pauses all application threads to run a
single VM thread that needs to know the heap is not going to change. GC is
one cause, others are (from Java Performance):
bq. There many other safepoints, such as biased locking revocation, thread
stack dumps, thread suspension or stopping (i.e., java.lang.Thread.stop()
method), and numerous inspection and modification operations requested
through JVMTI.
On my MBP (corei7, 16Gb, ssd) I ran cassandra with the stress test with
-XX:-PrintGCApplicationConcurrentTime and -XX:-PrintSafepointStatistics which
outputs information when the JVM exits. The biased-locking-tests.txt
attachment shows that stress took 1m 23 seconds to complete and the
safepoint statistics show most of the pauses were to revoke biased locks.
A second test was run (both with a clean data dir) with biased locking
disabled that took 1 minute 18 seconds. The safepoint stats did not include
any pauses to revoke biased locks
[jira] [Updated] (CASSANDRA-5360) Disable Thread Biased Locking in the JVM
[
https://issues.apache.org/jira/browse/CASSANDRA-5360?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
T Jake Luciani updated CASSANDRA-5360:
--
Fix Version/s: 1.2.4
Disable Thread Biased Locking in the JVM
Key: CASSANDRA-5360
URL: https://issues.apache.org/jira/browse/CASSANDRA-5360
Project: Cassandra
Issue Type: Improvement
Components: Core
Affects Versions: 1.0.12, 1.1.10, 1.2.3
Reporter: amorton
Assignee: amorton
Priority: Minor
Fix For: 1.2.4
Attachments: 5360.txt, cassandra-biased-locking-tests.txt
Biased Locking
(https://blogs.oracle.com/dave/entry/biased_locking_in_hotspot) is enabled by
default in JVM 6 and is designed to optimise applications where a locks are
normally used by one thread. This is the opposite of how the worker pools
cassandra work. Disabling Biased Locking (-XX:-UseBiasedLocking) has yielded
improvements of 5% to 10% in throughput and reduced JVM pauses.
Details follow.
h1. Application Pausing
The following was observed on a 16 core EC2 SSD instance...
{noformat}
Heap after GC invocations=32 (full 0):
par new generation total 1024000K, used 59799K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 0% used [0x0006fae0, 0x0006fae0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22592K, used 22578K
[0x0007fae0, 0x0007fc41, 0x0008)
}
Total time for which application threads were stopped: 0.0175680 seconds
Total time for which application threads were stopped: 0.0008680 seconds
Total time for which application threads were stopped: 0.0004030 seconds
Total time for which application threads were stopped: 0.0006460 seconds
Total time for which application threads were stopped: 0.0009210 seconds
Total time for which application threads were stopped: 0.0007250 seconds
Total time for which application threads were stopped: 0.0016340 seconds
Total time for which application threads were stopped: 0.0005570 seconds
Total time for which application threads were stopped: 0.0007270 seconds
Total time for which application threads were stopped: 0.0010170 seconds
Total time for which application threads were stopped: 0.0006240 seconds
Total time for which application threads were stopped: 0.0013250 seconds
{Heap before GC invocations=32 (full 0):
par new generation total 1024000K, used 878999K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 100% used [0x0006fae0, 0x00072ce0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22784K, used 22591K
[0x0007fae0, 0x0007fc44, 0x0008)
2013-03-15T21:21:17.015+: 1038.849: [GC Before GC:
Statistics for BinaryTreeDictionary:
{noformat}
The extra were stopped lines were annoying me, and the JVM Performance book
offered this explanation:
bq. If there happens to be additional safepoints between garbage collections,
the output will show Application time: and Total time for which application
threads were stopped: messages for each safepoint that occurs between garbage
collections.
h1. Safepoints
Safepoints are times when the JVM pauses all application threads to run a
single VM thread that needs to know the heap is not going to change. GC is
one cause, others are (from Java Performance):
bq. There many other safepoints, such as biased locking revocation, thread
stack dumps, thread suspension or stopping (i.e., java.lang.Thread.stop()
method), and numerous inspection and modification operations requested
through JVMTI.
On my MBP (corei7, 16Gb, ssd) I ran cassandra with the stress test with
-XX:-PrintGCApplicationConcurrentTime and -XX:-PrintSafepointStatistics which
outputs information when the JVM exits. The biased-locking-tests.txt
attachment shows that stress took 1m 23 seconds to complete and the
safepoint statistics show most of the pauses were to revoke biased locks.
A second test was run (both with a clean data dir) with biased locking
disabled that took 1 minute 18 seconds. The safepoint stats did not include
[jira] [Updated] (CASSANDRA-5360) Disable Thread Biased Locking in the JVM
[
https://issues.apache.org/jira/browse/CASSANDRA-5360?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
T Jake Luciani updated CASSANDRA-5360:
--
Fix Version/s: (was: 1.2.4)
Disable Thread Biased Locking in the JVM
Key: CASSANDRA-5360
URL: https://issues.apache.org/jira/browse/CASSANDRA-5360
Project: Cassandra
Issue Type: Improvement
Components: Core
Affects Versions: 1.0.12, 1.1.10, 1.2.3
Reporter: amorton
Assignee: amorton
Priority: Minor
Attachments: 5360.txt, cassandra-biased-locking-tests.txt
Biased Locking
(https://blogs.oracle.com/dave/entry/biased_locking_in_hotspot) is enabled by
default in JVM 6 and is designed to optimise applications where a locks are
normally used by one thread. This is the opposite of how the worker pools
cassandra work. Disabling Biased Locking (-XX:-UseBiasedLocking) has yielded
improvements of 5% to 10% in throughput and reduced JVM pauses.
Details follow.
h1. Application Pausing
The following was observed on a 16 core EC2 SSD instance...
{noformat}
Heap after GC invocations=32 (full 0):
par new generation total 1024000K, used 59799K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 0% used [0x0006fae0, 0x0006fae0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22592K, used 22578K
[0x0007fae0, 0x0007fc41, 0x0008)
}
Total time for which application threads were stopped: 0.0175680 seconds
Total time for which application threads were stopped: 0.0008680 seconds
Total time for which application threads were stopped: 0.0004030 seconds
Total time for which application threads were stopped: 0.0006460 seconds
Total time for which application threads were stopped: 0.0009210 seconds
Total time for which application threads were stopped: 0.0007250 seconds
Total time for which application threads were stopped: 0.0016340 seconds
Total time for which application threads were stopped: 0.0005570 seconds
Total time for which application threads were stopped: 0.0007270 seconds
Total time for which application threads were stopped: 0.0010170 seconds
Total time for which application threads were stopped: 0.0006240 seconds
Total time for which application threads were stopped: 0.0013250 seconds
{Heap before GC invocations=32 (full 0):
par new generation total 1024000K, used 878999K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 100% used [0x0006fae0, 0x00072ce0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22784K, used 22591K
[0x0007fae0, 0x0007fc44, 0x0008)
2013-03-15T21:21:17.015+: 1038.849: [GC Before GC:
Statistics for BinaryTreeDictionary:
{noformat}
The extra were stopped lines were annoying me, and the JVM Performance book
offered this explanation:
bq. If there happens to be additional safepoints between garbage collections,
the output will show Application time: and Total time for which application
threads were stopped: messages for each safepoint that occurs between garbage
collections.
h1. Safepoints
Safepoints are times when the JVM pauses all application threads to run a
single VM thread that needs to know the heap is not going to change. GC is
one cause, others are (from Java Performance):
bq. There many other safepoints, such as biased locking revocation, thread
stack dumps, thread suspension or stopping (i.e., java.lang.Thread.stop()
method), and numerous inspection and modification operations requested
through JVMTI.
On my MBP (corei7, 16Gb, ssd) I ran cassandra with the stress test with
-XX:-PrintGCApplicationConcurrentTime and -XX:-PrintSafepointStatistics which
outputs information when the JVM exits. The biased-locking-tests.txt
attachment shows that stress took 1m 23 seconds to complete and the
safepoint statistics show most of the pauses were to revoke biased locks.
A second test was run (both with a clean data dir) with biased locking
disabled that took 1 minute 18 seconds. The safepoint stats did not include
any pauses to
[jira] [Updated] (CASSANDRA-5360) Disable Thread Biased Locking in the JVM
[
https://issues.apache.org/jira/browse/CASSANDRA-5360?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
amorton updated CASSANDRA-5360:
---
Attachment: cassandra-biased-locking-tests.txt
Disable Thread Biased Locking in the JVM
Key: CASSANDRA-5360
URL: https://issues.apache.org/jira/browse/CASSANDRA-5360
Project: Cassandra
Issue Type: Improvement
Components: Core
Affects Versions: 1.0.12, 1.1.10, 1.2.3
Reporter: amorton
Priority: Minor
Attachments: cassandra-biased-locking-tests.txt
Biased Locking
(https://blogs.oracle.com/dave/entry/biased_locking_in_hotspot) is enabled by
default in JVM 6 and is designed to optimise applications where a locks are
normally used by one thread. This is the opposite of how the worker pools
cassandra work. Disabling Biased Locking (-XX:-UseBiasedLocking) has yielded
improvements of 5% to 10% in throughput and reduced JVM pauses.
Details follow.
h1. Application Pausing
The following was observed on a 16 core EC2 SSD instance...
{noformat}
Heap after GC invocations=32 (full 0):
par new generation total 1024000K, used 59799K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 0% used [0x0006fae0, 0x0006fae0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22592K, used 22578K
[0x0007fae0, 0x0007fc41, 0x0008)
}
Total time for which application threads were stopped: 0.0175680 seconds
Total time for which application threads were stopped: 0.0008680 seconds
Total time for which application threads were stopped: 0.0004030 seconds
Total time for which application threads were stopped: 0.0006460 seconds
Total time for which application threads were stopped: 0.0009210 seconds
Total time for which application threads were stopped: 0.0007250 seconds
Total time for which application threads were stopped: 0.0016340 seconds
Total time for which application threads were stopped: 0.0005570 seconds
Total time for which application threads were stopped: 0.0007270 seconds
Total time for which application threads were stopped: 0.0010170 seconds
Total time for which application threads were stopped: 0.0006240 seconds
Total time for which application threads were stopped: 0.0013250 seconds
{Heap before GC invocations=32 (full 0):
par new generation total 1024000K, used 878999K [0x0006fae0,
0x000745e0, 0x000745e0)
eden space 819200K, 100% used [0x0006fae0, 0x00072ce0,
0x00072ce0)
from space 204800K, 29% used [0x00072ce0, 0x000730865ff8,
0x00073960)
to space 204800K, 0% used [0x00073960, 0x00073960,
0x000745e0)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x000745e0, 0x0007fae0, 0x0007fae0)
concurrent-mark-sweep perm gen total 22784K, used 22591K
[0x0007fae0, 0x0007fc44, 0x0008)
2013-03-15T21:21:17.015+: 1038.849: [GC Before GC:
Statistics for BinaryTreeDictionary:
{noformat}
The extra were stopped lines were annoying me, and the JVM Performance book
offered this explanation:
bq. If there happens to be additional safepoints between garbage collections,
the output will show Application time: and Total time for which application
threads were stopped: messages for each safepoint that occurs between garbage
collections.
h1. Safepoints
Safepoints are times when the JVM pauses all application threads to run a
single VM thread that needs to know the heap is not going to change. GC is
one cause, others are (from Java Performance):
bq. There many other safepoints, such as biased locking revocation, thread
stack dumps, thread suspension or stopping (i.e., java.lang.Thread.stop()
method), and numerous inspection and modification operations requested
through JVMTI.
On my MBP (corei7, 16Gb, ssd) I ran cassandra with the stress test with
-XX:-PrintGCApplicationConcurrentTime and -XX:-PrintSafepointStatistics which
outputs information when the JVM exits. The biased-locking-tests.txt
attachment shows that stress took 1m 23 seconds to complete and the
safepoint statistics show most of the pauses were to revoke biased locks.
A second test was run (both with a clean data dir) with biased locking
disabled that took 1 minute 18 seconds. The safepoint stats did not include
any pauses to revoke biased locks (in attachment).
The
