G1GC: many consecutive full gcs (was Re: hotspot-gc-use Digest, Vol 40, Issue 4)

Mon Jun 27 17:46:16 UTC 2011

No smoking guns yet.

I should have asked for this earlier, sorry i forgot...
Could you share data from +PrintHeapAtGC +PrintHeapAtGCExtended ?

-- ramki

On 6/27/2011 6:43 AM, Stefan Wachter wrote:
> Hi Ramki,
>
> I took a heap dump and checked for WeakReferences and Finalizer objects.
>
> The heap dump contained 36,071,040 instances with 12,405 instances being WeakReference instances. I
> am not sure if this is a lot or not. The "Basic info" section that is displayed in NetBeans reports
> "Number of objects pending for finalization: 0". Corresponds this to the number of Finalizer objects
> you asked for?
>
> The complete heap summary is:
>
> Total bytes: 2,472,537,236
> Total classes: 15,953
> Total instances: 36,071,040
> Classloaders: 648
> GC roots: 3,138
> Number of objects pending for finalization: 0
>
>
> Cheers,
>
> Stefan
>
> On 06/17/2011 05:10 PM, Y. Srinivas Ramakrishna wrote:
>> Thanks for the responses and the extra information, Stefan and Alex.
>>
>> Stefan, please try PermSize == MaxPermSize at the next opportunity,
>> although it's likely not to have any effect based on a preliminary
>> reading of the info you provided below.
>>
>> As regards class histogram, please note that this would induce a
>> pause as long as the full gc's you see (or may be a bit shorter),
>> so use it with care when you obtain that information.
>>
>> Meanwhile, we'll look over the information you have provided and
>> get back to you once we have made some headway. Thanks for bringing
>> this to our attention and for the data so far.
>>
>> -- ramki
>>
>> On 6/17/2011 12:00 AM, Stefan Wachter wrote:
>>> Hi Ramki,
>>>
>>> thanks for your interest. See my answers below.
>>>
>>> Cheers,
>>>
>>> Stefan
>>>
>>>
>>> On 06/17/2011 12:20 AM, Y. S. Ramakrishna wrote:
>>>> Stefan and Alex --
>>>>
>>>> (1) what's the version of the JVM used?
>>>
>>> Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
>>> Java HotSpot(TM) 64-Bit Server VM (build 19.1-b02, mixed mode)
>>>
>>>>
>>>> (2) could you try PermSize == MaxPermSize and see if it made any
>>>> difference?
>>>
>>> PermSize was not set until now. I try this setting and can report results the next time our cluster
>>> nodes are switched.
>>>
>>>>
>>>> (3) do you have lots of WeakReference or Finalizer objects in your system?
>>>
>>> I have no information about this. I guess a heap dump would provide that information. I will ask our
>>> admins if it is possible to take a heap dump.
>>>
>>>>
>>>> (4) is what you have below your complete GC log (i.e. no gaps between first and last line?)
>>>
>>> Yes, that is the original output of the GC. No lines were removed.
>>>>
>>>> (5) what do you see when using CMS (in case you tried it)?
>>>
>>> CMS seems to behave better (see attached gc.log). The settings used with CMS are:
>>>
>>> -Xmx10000M
>>> -Xms1024M
>>> -XX:MaxPermSize=1024m
>>> -XX:+PrintGCDateStamps
>>> -XX:+UseConcMarkSweepGC
>>>
>>>>
>>>> (6) do you have a simple test case that you can share with
>>>> us that exhibits this behaviour?
>>>
>>> Unfortunately I have no simple test case. The output is from our life system running a tomcat with
>>> various wars deployed.
>>>
>>>>
>>>> thanks!
>>>> -- ramki
>>>>
>>>> On 06/16/11 14:02, Alex Aisinzon wrote:
>>>>> Stefan
>>>>>
>>>>> I have had similar experience with G1 and reported it here.
>>>>> I tried the option to try to limit GC pauses (-XX:MaxGCPauseMillis with
>>>>> 1s and then 2s). It did not improve things.
>>>>> I am happy to try anything else to help improve G1.
>>>>>
>>>>> Alex A
>>>>>
>>>>> -----Original Message-----
>>>>> From: hotspot-gc-use-bounces at openjdk.java.net
>>>>> [mailto:hotspot-gc-use-bounces at openjdk.java.net] On Behalf Of
>>>>> hotspot-gc-use-request at openjdk.java.net
>>>>> Sent: Thursday, June 16, 2011 12:00 PM
>>>>> To: hotspot-gc-use at openjdk.java.net
>>>>> Subject: hotspot-gc-use Digest, Vol 40, Issue 4
>>>>>
>>>>> 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. G1GC: many consecutive full gcs (Stefan Wachter)
>>>>>
>>>>>
>>>>> ----------------------------------------------------------------------
>>>>>
>>>>> Message: 1
>>>>> Date: Thu, 16 Jun 2011 09:23:05 +0200
>>>>> From: Stefan Wachter <Stefan.Wachter at gmx.de>
>>>>> Subject: G1GC: many consecutive full gcs
>>>>> To: hotspot-gc-use at openjdk.java.net
>>>>> Message-ID: <4DF9AF59.90708 at gmx.de>
>>>>> Content-Type: text/plain; charset=ISO-8859-1; format=flowed
>>>>>
>>>>> Hi all,
>>>>>
>>>>> the G1GC runs nicely for some time but then it starts to have bursts of consecutive full gcs (see
>>>>> log below). Can anyone explain that behaviour?
>>>>>
>>>>> The JVM is stared with these options:
>>>>>
>>>>> -Xmx10000M
>>>>> -Xms1024M
>>>>> -XX:MaxPermSize=1024m
>>>>> -XX:+UseG1GC
>>>>> -XX:MaxGCPauseMillis=2000
>>>>> -XX:GCPauseIntervalMillis=10000
>>>>>
>>>>> --Stefan
>>>>>
>>>>>
>>>>> 31314.569: [GC pause (young) 3286M->3234M(8937M), 0.0485530 secs]
>>>>> 31374.932: [GC pause (young) 3279M->3236M(8937M), 0.0486560 secs]
>>>>> 31837.688: [GC pause (young) 4614M->3252M(8937M), 0.0739370 secs]
>>>>> 33528.784: [GC pause (young) 5997M->3330M(8937M), 0.1543940 secs]
>>>>> 35372.029: [GC pause (young) 6038M->3405M(8937M), 0.2364930 secs]
>>>>> 36508.343: [Full GC 8525M->2903M(9678M), 8.9121160 secs]
>>>>> 38204.291: [Full GC 8647M->2295M(10000M), 7.4105940 secs]
>>>>> 39038.017: [Full GC 8790M->2092M(6975M), 6.7242110 secs]
>>>>> 39047.736: [Full GC 8996M->2089M(9998M), 6.0741630 secs]
>>>>> 39095.551: [Full GC 8936M->2090M(6969M), 5.5573390 secs]
>>>>> 39104.326: [Full GC 9175M->2092M(9997M), 5.3413860 secs]
>>>>> 39112.760: [Full GC 9392M->2094M(9978M), 5.4884150 secs]
>>>>> 41965.304: [Full GC 9549M->2112M(7043M), 6.4774550 secs]
>>>>> 43830.656: [GC pause (young) 4615M->2309M(7043M), 0.1727720 secs]
>>>>> 46024.398: [GC pause (young) 4638M->2497M(7043M), 0.3039900 secs]
>>>>> 46068.009: [Full GC 8832M->2237M(10000M), 6.6717340 secs]
>>>>> 46077.691: [Full GC 9322M->2187M(9987M), 5.8603570 secs]
>>>>> 46086.731: [Full GC 9487M->2189M(9996M), 5.8521360 secs]
>>>>> 46124.713: [Full GC 8792M->2185M(9895M), 5.7782260 secs]
>>>>> 46133.366: [Full GC 9297M->2188M(9999M), 5.7263360 secs]
>>>>> 46142.238: [Full GC 9509M->2189M(9985M), 5.5704850 secs]
>>>>> 47454.530: [Full GC 9676M->2295M(7653M), 7.3169840 secs]
>>>>> 48163.422: [GC pause (young) 4937M->2431M(7653M), 0.2379570 secs]
>>>>> 48887.388: [GC pause (young) 5007M->2497M(7653M), 0.1999790 secs]
>>>>>
>>>>>
>>>>>
>>>>> ------------------------------
>>>>>
>>>>> _______________________________________________
>>>>> 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 40, Issue 4
>>>>> *********************************************
>>>>> _______________________________________________
>>>>> hotspot-gc-use mailing list
>>>>> hotspot-gc-use at openjdk.java.net
>>>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>>
>>>
>>
>>
>

_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use