[
https://issues.apache.org/jira/browse/CASSANDRA-5360?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13605915#comment-13605915
]
amorton commented on CASSANDRA-5360:
------------------------------------
bq. Were you able to test disabling biased locking on the 16 core box?
Testing it now, giving the JVM some time to settle down. Unfortunately
PrintSafepointStatistics only outputs when the JVM shuts down, make's it hard
to observe on a running server.
bq. This is new to me, what else causes pauses?
The Safepoint's in the PrintSafepointStatistics output were Deoptimize, no vm
operation and GenCollectForAllocation
> 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 [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
