cassandra-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "amorton (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (CASSANDRA-5360) Disable Thread Biased Locking in the JVM
Date Tue, 19 Mar 2013 01:27:15 GMT

    [ 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

Mime
View raw message