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

[Stefan Wachter]

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
>>>
>>
>
>