amorton created CASSANDRA-5360:
----------------------------------
Summary: 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.2.3, 1.1.10, 1.0.12
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 [0x00000006fae00000,
0x0000000745e00000, 0x0000000745e00000)
eden space 819200K, 0% used [0x00000006fae00000, 0x00000006fae00000,
0x000000072ce00000)
from space 204800K, 29% used [0x000000072ce00000, 0x0000000730865ff8,
0x0000000739600000)
to space 204800K, 0% used [0x0000000739600000, 0x0000000739600000,
0x0000000745e00000)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x0000000745e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 22592K, used 22578K [0x00000007fae00000,
0x00000007fc410000, 0x0000000800000000)
}
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 [0x00000006fae00000,
0x0000000745e00000, 0x0000000745e00000)
eden space 819200K, 100% used [0x00000006fae00000, 0x000000072ce00000,
0x000000072ce00000)
from space 204800K, 29% used [0x000000072ce00000, 0x0000000730865ff8,
0x0000000739600000)
to space 204800K, 0% used [0x0000000739600000, 0x0000000739600000,
0x0000000745e00000)
concurrent mark-sweep generation total 2965504K, used 416618K
[0x0000000745e00000, 0x00000007fae00000, 0x00000007fae00000)
concurrent-mark-sweep perm gen total 22784K, used 22591K [0x00000007fae00000,
0x00000007fc440000, 0x0000000800000000)
2013-03-15T21:21:17.015+0000: 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 GC logs did show some application pauses not related to GC, which are also
included in the safepoint output and not related to revoking biased locks.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
