G1 GC - [Ref Enq] taking lot of time

[Gopal, Prasanna CWK]

Hi All

We are experimenting G1 GC for one of our application.  Please find our application settings GC Settings

-XX:MaxPermSize=512m
 -XX:+UseG1GC
 -XX:G1ReservePercent=40
 -XX:ConcGCThreads=14
 -XX:+PrintGCDateStamps
-XX:+PrintTenuringDistribution
 -XX:+PrintGCApplicationConcurrentTime
 -XX:+PrintGCApplicationStoppedTime

JVM : JVM : jdk_7u40_x64

While scanning for instances which caused application threads to get stopped , we found the following instance in our GC logs.

GC Logs
=======


{Heap before GC invocations=57832 (full 1):
garbage-first heap   total 5242880K, used 3111240K [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)
  region size 2048K, 672 young (1376256K), 1 survivors (2048K)
compacting perm gen  total 98304K, used 96772K [0x00000007e0000000, 0x00000007e6000000, 0x0000000800000000)
   the space 98304K,  98% used [0x00000007e0000000, 0x00000007e5e81338, 0x00000007e5e81400, 0x00000007e6000000)
No shared spaces configured.
2016-10-05T12:13:19.835-0400: 80080.725: [GC pause (young)
Desired survivor size 88080384 bytes, new threshold 15 (max 15)
- age   1:     136824 bytes,     136824 total
- age   2:      11120 bytes,     147944 total
- age   3:      11408 bytes,     159352 total
- age   4:       9248 bytes,     168600 total
- age   5:       8632 bytes,     177232 total
- age   6:       8224 bytes,     185456 total
- age   7:       8784 bytes,     194240 total
- age   8:      87856 bytes,     282096 total
- age   9:      25080 bytes,     307176 total
- age  10:       8272 bytes,     315448 total
- age  11:       7984 bytes,     323432 total
- age  12:      14120 bytes,     337552 total
- age  13:       9824 bytes,     347376 total
- age  14:      11616 bytes,     358992 total
- age  15:       8032 bytes,     367024 total
, 51.2453720 secs]
   [Parallel Time: 11.3 ms, GC Workers: 16]
      [GC Worker Start (ms): Min: 80080725.7, Avg: 80080725.8, Max: 80080725.9, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 4.4, Avg: 5.2, Max: 10.7, Diff: 6.3, Sum: 83.5]
      [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.3, Diff: 1.3, Sum: 13.4]
         [Processed Buffers: Min: 0, Avg: 3.0, Max: 7, Diff: 7, Sum: 48]
      [Scan RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 3.7]
      [Object Copy (ms): Min: 0.1, Avg: 0.4, Max: 0.6, Diff: 0.5, Sum: 6.0]
      [Termination (ms): Min: 0.0, Avg: 4.3, Max: 4.6, Diff: 4.6, Sum: 68.6]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.0]
      [GC Worker Total (ms): Min: 10.9, Avg: 11.0, Max: 11.2, Diff: 0.3, Sum: 176.3]
      [GC Worker End (ms): Min: 80080736.7, Avg: 80080736.8, Max: 80080736.8, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.4 ms]
   [Other: 51233.7 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 17.2 ms]
      [Ref Enq: 50800.9 ms]
      [Free CSet: 381.2 ms]
   [Eden: 1342.0M(1342.0M)->0.0B(254.0M) Survivors: 2048.0K->2048.0K Heap: 3038.3M(5120.0M)->1696.2M(5120.0M)]
Heap after GC invocations=57833 (full 1):
 garbage-first heap   total 5242880K, used 1736897K [0x00000006a0000000, 0x00000007e0000000, 0x00000007e0000000)
  region size 2048K, 1 young (2048K), 1 survivors (2048K)
compacting perm gen  total 98304K, used 96772K [0x00000007e0000000, 0x00000007e6000000, 0x0000000800000000)
   the space 98304K,  98% used [0x00000007e0000000, 0x00000007e5e81338, 0x00000007e5e81400, 0x00000007e6000000)
No shared spaces configured.
}
[Times: user=0.00 sys=17.51, real=51.28 secs]
2016-10-05T12:14:11.208-0400: 80132.098: Total time for which application threads were stopped: 51.3791600 seconds

It looks like Reference  Enqueue ( Ref Enq)  event took nearly 50 seconds to complete. Could  you please help me in understanding , why it might take so much time to complete. Do I need to add any diagnostic flag to get more information ?.  Apologies , If  similar question was answered before in the mailing list. Any help is really appreciated.

Thanks and Regards
Prasanna



This message may contain information that is confidential or privileged. If you are not the intended recipient, please advise the sender immediately and delete this message. See http://www.blackrock.com/corporate/en-us/compliance/email-disclaimers for further information.  Please refer to http://www.blackrock.com/corporate/en-us/compliance/privacy-policy for more information about BlackRock’s Privacy Policy.
BlackRock Advisors (UK) Limited and BlackRock Investment Management (UK) Limited are authorised and regulated by the Financial Conduct Authority. Registered in England No. 796793 and No. 2020394 respectively. BlackRock Life Limited is authorised by the Prudential Regulation Authority and regulated by the Financial Conduct Authority and the Prudential Regulation Authority. Registered in England No. 2223202. Registered Offices: 12 Throgmorton Avenue, London EC2N 2DL. BlackRock International Limited is authorised and regulated by the Financial Conduct Authority and is a registered investment adviser with the Securities and Exchange Commission (SEC). Registered in Scotland No. SC160821. Registered Office: Exchange Place One, 1 Semple Street, Edinburgh EH3 8BL.
For a list of BlackRock's office addresses worldwide, see http://www.blackrock.com/corporate/en-us/about-us/contacts-locations.

© 2016 BlackRock, Inc. All rights reserved.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20161006/97793b67/attachment-0001.html>