Need help on long minor GC pause
Avinash Mishra
pingavinash at yahoo.com
Thu Sep 12 13:17:23 PDT 2013
Here is the entire GC log we have from the tests:
2013-09-12T10:06:59.222-0700: 120850.013: [GC Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 37567788
Max Chunk Size: 19517862
Number of Blocks: 21
Av. Block Size: 1788942
Tree Height: 8
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3635496
Max Chunk Size: 3634176
Number of Blocks: 3
Av. Block Size: 1211832
Tree Height: 2
120850.013: [ParNew120865.142: [SoftReference, 0 refs, 0.0000052 secs]120865.142: [WeakReference, 1 refs, 0.0000022 secs]120865.142: [FinalReference, 0 refs, 0.0000014 secs]120865.142: [PhantomReference, 2 refs, 0.0000018 secs]120865.142: [JNI Weak Reference, 0.0000014 secs]: 59007K->6528K(59008K), 15.1290884 secs] 893600K->843004K(1042048K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 37142932
Max Chunk Size: 19517862
Number of Blocks: 20
Av. Block Size: 1857146
Tree Height: 8
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3635496
Max Chunk Size: 3634176
Number of Blocks: 3
Av. Block Size: 1211832
Tree Height: 2
, 15.1295291 secs] [Times: user=0.13 sys=0.00, real=15.13 secs]
Total time for which application threads were stopped: 15.1305786 seconds
Application time: 0.0054168 seconds
Total time for which application threads were stopped: 0.0454332 seconds
Application time: 0.0003027 seconds
Total time for which application threads were stopped: 0.0005096 seconds
Application time: 0.0208497 seconds
Total time for which application threads were stopped: 0.4512979 seconds
Application time: 1.7480473 seconds
Total time for which application threads were stopped: 0.4840827 seconds
Application time: 0.0001481 seconds
Total time for which application threads were stopped: 0.5162972 seconds
Application time: 0.9989582 seconds
Total time for which application threads were stopped: 1.9044960 seconds
Application time: 0.0033451 seconds
Total time for which application threads were stopped: 0.0078556 seconds
Application time: 0.0005994 seconds
Total time for which application threads were stopped: 0.0347992 seconds
Application time: 0.0001253 seconds
Total time for which application threads were stopped: 0.0004586 seconds
Application time: 0.0001029 seconds
Total time for which application threads were stopped: 0.0004276 seconds
Application time: 0.0020670 seconds
Total time for which application threads were stopped: 0.0328372 seconds
Application time: 0.0003629 seconds
Total time for which application threads were stopped: 0.0407637 seconds
Application time: 0.0004604 seconds
Total time for which application threads were stopped: 0.0095295 seconds
Application time: 0.0013711 seconds
Total time for which application threads were stopped: 0.4448677 seconds
Application time: 0.0010127 seconds
Total time for which application threads were stopped: 0.1862938 seconds
Application time: 0.0004584 seconds
Total time for which application threads were stopped: 2.3634920 seconds
Application time: 0.0006381 seconds
Total time for which application threads were stopped: 1.2755493 seconds
Application time: 0.0000791 seconds
Total time for which application threads were stopped: 0.0003866 seconds
Application time: 0.0004948 seconds
Total time for which application threads were stopped: 0.0070434 seconds
Application time: 0.0023128 seconds
Total time for which application threads were stopped: 0.0105626 seconds
Application time: 0.0010711 seconds
Total time for which application threads were stopped: 0.0265656 seconds
Application time: 0.0008076 seconds
Total time for which application threads were stopped: 0.0599900 seconds
Application time: 0.0001002 seconds
Total time for which application threads were stopped: 0.0205268 seconds
Application time: 0.0072575 seconds
Total time for which application threads were stopped: 0.9417735 seconds
Application time: 0.0005076 seconds
Total time for which application threads were stopped: 0.7657093 seconds
Application time: 0.0017558 seconds
Total time for which application threads were stopped: 0.1212358 seconds
Application time: 0.0014846 seconds
Total time for which application threads were stopped: 0.5607651 seconds
Application time: 0.0051868 seconds
Total time for which application threads were stopped: 0.3071135 seconds
Application time: 0.0002792 seconds
Total time for which application threads were stopped: 0.0761226 seconds
Application time: 0.0008392 seconds
Total time for which application threads were stopped: 0.0004832 seconds
Application time: 0.0022389 seconds
Total time for which application threads were stopped: 0.0004443 seconds
Application time: 0.0003162 seconds
Total time for which application threads were stopped: 0.0003712 seconds
Application time: 0.0003393 seconds
Total time for which application threads were stopped: 0.0004577 seconds
Application time: 0.0011367 seconds
Total time for which application threads were stopped: 0.0004018 seconds
Application time: 2.1982655 seconds
Total time for which application threads were stopped: 0.0008523 seconds
Application time: 1.9970691 seconds
Total time for which application threads were stopped: 0.0168507 seconds
Application time: 0.9985377 seconds
Total time for which application threads were stopped: 0.0826776 seconds
Application time: 5.7725220 seconds
Total time for which application threads were stopped: 0.1754836 seconds
Application time: 0.0000573 seconds
Total time for which application threads were stopped: 0.0031288 seconds
Application time: 0.0003676 seconds
Total time for which application threads were stopped: 0.0059951 seconds
Application time: 0.9894649 seconds
Total time for which application threads were stopped: 0.0008202 seconds
Application time: 1.9994647 seconds
Total time for which application threads were stopped: 0.0008728 seconds
Application time: 1.9979438 seconds
Total time for which application threads were stopped: 0.0008308 seconds
Application time: 7.9974667 seconds
Total time for which application threads were stopped: 0.0008303 seconds
Application time: 2.9985472 seconds
Total time for which application threads were stopped: 0.0008017 seconds
Application time: 4.7325503 seconds
Total time for which application threads were stopped: 0.0008595 seconds
Application time: 0.0304200 seconds
Total time for which application threads were stopped: 0.0003669 seconds
Application time: 1.2493383 seconds
Total time for which application threads were stopped: 0.0008296 seconds
Application time: 0.3115816 seconds
Total time for which application threads were stopped: 0.0007282 seconds
Application time: 0.0616963 seconds
Total time for which application threads were stopped: 0.0004873 seconds
Application time: 0.3744796 seconds
Total time for which application threads were stopped: 0.0007073 seconds
Application time: 0.2023382 seconds
Total time for which application threads were stopped: 0.0004948 seconds
Application time: 0.1857517 seconds
________________________________
From: Avinash Mishra <pingavinash at yahoo.com>
To: "hotspot-gc-use at openjdk.java.net" <hotspot-gc-use at openjdk.java.net>
Sent: Friday, 13 September 2013 1:43 AM
Subject: Need help on long minor GC pause
Hi folks,
Thanks for the quick feedback. We got lucky with the issue and got these logs today:
120850.013: [ParNew120865.142: [SoftReference, 0 refs, 0.0000052 secs]120865.142: [WeakReference, 1 refs, 0.0000022 secs]120865.142: [FinalReference, 0 refs, 0.0000014 secs]120865.142: [PhantomReference, 2 refs, 0.0000018 secs]120865.142: [JNI Weak Reference, 0.0000014 secs]: 59007K->6528K(59008K), 15.1290884 secs] 893600K->843004K(1042048K)After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 37142932
Max Chunk Size: 19517862
Number of Blocks: 20
Av. Block Size: 1857146
Tree Height: 8
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 3635496
Max Chunk Size: 3634176
Number of Blocks: 3
Av. Block Size: 1211832
Tree Height: 2
, 15.1295291 secs] [Times: user=0.13 sys=0.00, real=15.13 secs]
So you were probably right about swapping to be the potential issue. The strange thing is that its we have 8GB of RAM on the server and only 2.5 GB is used.
Could you please suggest us on how can we confirm if its a swapping issue (we do have perfmons). Also, please suggest how we can fix this problem on Windows server.
Regards,
Avinash
________________________________
From: "hotspot-gc-use-request at openjdk.java.net" <hotspot-gc-use-request at openjdk.java.net>
To: hotspot-gc-use at openjdk.java.net
Sent: Wednesday, 11 September 2013 3:24 PM
Subject: hotspot-gc-use Digest, Vol 67, Issue 2
Send hotspot-gc-use mailing list submissions to
hotspot-gc-use at openjdk.java.net
To subscribe or unsubscribe via the World Wide Web, visit
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
or, via email, send a message with subject or body 'help' to
hotspot-gc-use-request at openjdk.java.net
You can reach the person managing the list at
hotspot-gc-use-owner at openjdk.java.net
When replying, please edit your Subject line so it is more specific
than "Re: Contents of hotspot-gc-use digest..."
Today's Topics:
1. Re: Need help on long minor GC pause (W?thrich J?rg)
----------------------------------------------------------------------
Message: 1
Date: Wed, 11 Sep 2013 11:54:16 +0200
From: W?thrich J?rg <jwu at gmx.ch>
Subject: Re: Need help on long minor GC pause
To: hotspot-gc-use at openjdk.java.net
Message-ID: <52303DC8.5000801 at gmx.ch>
Content-Type: text/plain; charset="iso-8859-1"
Hi Avinash,
If it turns out to be a fragmentation issue, you might want to consider
upgrading to a newer java version, because 1.6u25 and above have serious
improvements concerning fragmentation
(http://blog.ragozin.info/2011/10/java-cg-hotspots-cms-and-heap.html).
One place where I saw very long pauses with fragmentation was when
concurrent mode failures occurred. I am not sure if
fragmentation
affects minor GCs so much.
You might also want to follow another lead: swapping. GC logs also
contain the "|Times:user=2.19sys=1.35,real=385.50secs]" in the end of
the lines. If "real" is much longer than "user"+"sys" your system might
be swapping.|
|||
Regards,
J?rg
|Am 11.09.2013 10:24, schrieb Avinash Mishra:
> Hi folks,
>
> We are facing a strange issue where the minor GC gets stuck for
> several seconds:
>
> 734827.324: [GC 639235K->587610K(1042048K), 2.4140118 secs]
> 734846.488: [GC 640090K->589859K(1042048K), 22.1046232 secs]
> 734949.577: [GC 642339K->590078K(1042048K), 12.2527731 secs]
> 735045.592: [GC 642558K->591084K(1042048K), 0.1158979 secs]
> Our Java configuration is something like this:
>
> java -Xms1024m -Xmx1024m -XX:+UseConcMarkSweepGC -cp %MY_CLASSPATH%
> com.myclass
>
> We are
using Java 1.6u24 and the application is running on a Windows
> 2003 server.
>
> The issue is specific to a couple of servers at a customer site and
> nowhere else. The servers here run fine for up to some 45 days when
> the issue shows up.
>
> From the logs(above) it seems that there is plenty of old space
> available on heap so we have ruled out concurrent failures. We are
> looking into fragmentation as the potential root cause. We have
> enabled these traces to confirm if we have a fragmentation issue
>
> -XX:+PrintGCDetails
> -XX:+PrintPromotionFailure
> -XX:PrintFLSStatistics=1
>
> From these logs we are monitoring "Max chunk available" and look for a
> decrease in trend to determine if the servers are heading towards a
> fragmentation problem. Please let me know if anything else is required
> to confirm on fragmentation issue
and if there is a a way to confirm
> it sooner instead of waiting for couple of months.
>
> Please let me know if you have any other pointers on potential root cause.
>
> Thanks,
> Avinash
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130911/d331fa67/attachment.html
------------------------------
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
End of hotspot-gc-use Digest, Vol 67, Issue 2
*********************************************
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130913/110b9875/attachment-0001.html
More information about the hotspot-gc-use
mailing list