CMS collection keep working during holiday

[Y. Srinivas Ramakrishna]

Hi Kirk --

> of course... look at this
>
> VM optoins: -Djava.security.policy=.\java.policy -Xms1536M -Xmx1536M
> -XX:NewSize=256M -XX:+PrintGCDetails -XX:+PrintGCTaskTimeStamps
> -XX:+PrintHeapAtGC -Xloggc:gc.log -XX:+PrintReferenceGC
> -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
> -XX:SurvivorRatio=4 -XX:CMSInitiatingOccupancyFraction=55
> -XX:TargetSurvivorRatio=90 -XX:SoftRefLRUPolicyMSPerMB=0
> -Dcom.sun.management.jmxremote.port=18002
> -Dcom.sun.management.jmxremote.authenticate=false
> -Dcom.sun.management.jmxremote.ssl=false

Thanks for confirming.

>
> Perm space is ignored! Does he need to add
> -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled

Right; however, as of 6.0, the second flag is not needed; just
-XX:+CMSClassUnloadingEnabled should suffice.

-- ramki

>
> Kirk
>
>
> Y Srinivas Ramakrishna wrote:
> > The mention of class loaders below reminds me to remind you that
> > CMS by default will not collect class objects. To force CMS
> > to collect classes in the perm gen, you would want to
> > -XX:+CMSClassUnloadingEnabled. Try to see if that made any
> > difference to the apparent inability of CMS to collect
> > those apparently otherwise unreachable objects.
> >
> > -- ramki
> >
> > ----- Original Message -----
> > From: "Ken--@..." <dragonken@...>
> > Date: Thursday, October 9, 2008 3:10 am
> > Subject: Re: CMS collection keep working during holiday
> > To: hotspot-gc-dev@...
> >
> >
> >  
> >> Hi,
> >>
> >> I have jhat the vm heap but I don't know how to trace the problem.
> I tried
> >> to click HashMap$Entry / HashMap and there is so many instances and
>
> >> halt my
> >> browser. I found many references to HashMap are
> >>
> >> com.sun.jmx.remote.util.OrderClassLoaders@0x49448a18 (54 bytes) : field
> >> packages
> >> sun.rmi.server.LoaderHandler$Loader@0x17be85d0 (75 bytes) : field packages
> >> java.security.BasicPermissionCollection@0x40b740e8 (18 bytes) :
> field
> >> perms
> >>
> >> Up to now, I believe my application has no memory leaks as my
> >> application is
> >> running very well without CMS collector and DisableExplicitGC. But
> I need
> >> CMS and DisableExplicitGC in order to have short gc pause time.
> >>
> >> There must be somewhere fool the CMS collector. Any idea to shoot the
> >> problem? Is that my application problem or jvm itself?
> >>
> >> Thanks and Best Regards,
> >> Ken
> >> --
> >> View this message in context: http://www.nabble.com/CMS-collection-keep-working-during-holiday-tp19773575p19895899.html
> >> Sent from the OpenJDK Hotspot Garbage Collection mailing list
> archive
> >> at Nabble.com.
> >>
> >>    
> >
> >  
>

[Peter B. Kessler]

Would it be diagnostic to get a "jmap -histo" right after a CMS cycle
completes (e.g., by watching the GC log), followed immediately by a
"jmap -histo:live" to force a full compacting GC?  Differencing those
might tell you what CMS isn't seeing.  There will be some "fuzz" in the
result because the application continues running and allocating
short-lived objects, e.g., during the concurrent mark and concurrent
sweep, and which the full collection will collect, but maybe someone who
knows the application could see past the differences in short-lived stuff.

                        ... peter

Tony Printezis wrote:

>
> Y Srinivas Ramakrishna wrote:
>> If you use jmap -histo:live <pid> from the command-line you will
>> get a full gc before the histogram is computed. This full gc will
>> be done despite having +DisableExplicitGC.
>>  
> In fact, given that we want to find out what's growing in the heap
> during the CMS cycles (which seems to be GCed during Full GCs), it's
> better to use jmap -histo (i.e., no :live) to avoid the Full GC. But I'm
> forgetting: which VM Ken using? IIRC only jmap in 6 has the :live / no
> :live functionality (before that, it always did a Full GC, which is not
> what you want some of the time).
>
> Tony
>

Thanks to all of you. It seems work after adding -XX:+CMSClassUnloadingEnabled as you suggested.

So, why classloader create so many HashMap entries and Vector elements? It seems that only a few people have this problem.

vm options:

-server -showversion -Djava.security.policy=.\java.policy -Xms1536M -Xmx1536M -XX:NewSize=256M -XX:+PrintGCDetails -XX:+PrintGCTaskTimeStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -Xloggc:gc.log -XX:+PrintReferenceGC -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:SurvivorRatio=4 -XX:CMSInitiatingOccupancyFraction=55 -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -XX:MaxTenuringThreshold=1 -XX:SoftRefLRUPolicyMSPerMB=0 -Dcom.sun.management.jmxremote.port=18002 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false


gc log:
gc.log

jconsole:





> Y Srinivas Ramakrishna wrote:
> > The mention of class loaders below reminds me to remind you that
> > CMS by default will not collect class objects. To force CMS
> > to collect classes in the perm gen, you would want to
> > -XX:+CMSClassUnloadingEnabled. Try to see if that made any
> > difference to the apparent inability of CMS to collect
> > those apparently otherwise unreachable objects.
> >
> > -- ramki
> >
> > ----- Original Message -----
> > From: "[e-mail]" <[e-mail]>
> > Date: Thursday, October 9, 2008 3:10 am
> > Subject: Re: CMS collection keep working during holiday
> > To: [e-mail]
> >
> >

[Y. Srinivas Ramakrishna]

Hi Ken -- Good to know that your main problem was solved.

> Thanks to all of you. It seems work after adding
> -XX:+CMSClassUnloadingEnabled as you suggested.
>
> So, why classloader create so many HashMap entries and Vector
> elements? It
> seems that only a few people have this problem.

I suspect that if you used jconsole to track the #classes loaded,
it would likely show an unbounded upward trend (or at least
an upward trend that would correlate with the slope of the lower
envelope of the old generation occupancy).

The vectors are class loaders that your application container(s)
use to load classes. The problem with CMS's default of not concurrently
collecting classes here is that the classes which live in the perm gen
point to their class loaders which live in the regular heap (old gen,
eventually). So the class loaders do not get collected either. Further,
the uncollected classes may have heavy-weight static fields associated
with them (data which again lives in the regular heap). Thus what might
be a few small classes that we schlep around in our perm gen, might be
holding onto a lot of garbage that collects in the old gen.

That's what we saw in your application.

It so happens that in some cases you can actually clearly see the
deleterious effect of accumulating perm gen garbage on the performance
of not only CMS (which, as in your case, had an artifically bloated
footprint and was running useless cycles), but on scavenges --
the latter is two-fold: firstly the quasi-immortal (modulo
mark-compact which reclaims them) class loaders and other class-cohorts
act as barriers to coalition and tend to fragment the old gen, causing
much pain to scavenges, which slow down over time; further,
the dead classes in the perm gen act as "dead roots" that inflates
the root-scanning time for scavenges and further slows down scavenges.
In a recent exchange, i think on this list, we saw a nice expample
of that. We can probably extract a time-series plot of the scavenge
times from your logs to see if we see a similar trending which
is often a signature of problems such as these. (Of course similar
signatures would appear also with some memory leaks, as Tony and Kirk
suspected earlier.)

Now a word about the default setting of CMSClassUnloadingEnabled. This setting
was selected a number of years ago when it was relatively uncommon to
have applications running in containers. In such cases, one would
expect a small upper bound on the number of classes an application
would load and thus it did not hurt much to not unload unreachable
classes, thus avoid the extra work that CMS would need to do especially
during the stop-world remark pause. That default setting however appears
to be the wrong setting for the way a large majority of the applications
are run today inside containers which causes a proliferation of classes
and loaders.

We have had a bug [1] filed for flipping the switch for a while but have not
bitten the bullet and either take the resulting hit on CMS remark times
(or appropriately deal with it; [2] is only one of several possibilities
here). I think we'll address [1] soon, so that most users (such as Ken
 would not have to worry about this setting. Instead, power users
who know what they are doing andcan compute a sufficiently small
and tight upper bound on the total number and size of classes
(and cohorts) they load during the life of their application
would be required to throw off the switch explicitly.
In my own recent (and admittedly somewhat biased) experience,
the fraction of applications for which a non-trivial upper bound
exists has been shrinking over time as more and more applications
deploy on Java EE / application servers / containers.

Comments, votes, plebiscite?

-- ramki

[1] 6329603 CMS: +CMSClassUnloadingEnabled and +CMSPermGenSweepingEnabled by default
[2] 6543076 CMS: Adaptive collection of perm gen

>
> vm options:
>
> -server -showversion -Djava.security.policy=.\java.policy -Xms1536M
> -Xmx1536M -XX:NewSize=256M -XX:+PrintGCDetails -XX:+PrintGCTaskTimeStamps
> -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -Xloggc:gc.log
> -XX:+PrintReferenceGC -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC
> -XX:+UseParNewGC -XX:SurvivorRatio=4 -XX:CMSInitiatingOccupancyFraction=55
> -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled
> -XX:MaxTenuringThreshold=1 -XX:SoftRefLRUPolicyMSPerMB=0
> -Dcom.sun.management.jmxremote.port=18002
> -Dcom.sun.management.jmxremote.authenticate=false
> -Dcom.sun.management.jmxremote.ssl=false
>
>
> gc log:
> http://www.nabble.com/file/p19912471/gc.log gc.log
>
> jconsole:
> http://www.nabble.com/file/p19912471/jconsole_20081010.jpg 
>
>
>
>
> > Y Srinivas Ramakrishna wrote:
> > > The mention of class loaders below reminds me to remind you that
> > > CMS by default will not collect class objects. To force CMS
> > > to collect classes in the perm gen, you would want to
> > > -XX:+CMSClassUnloadingEnabled. Try to see if that made any
> > > difference to the apparent inability of CMS to collect
> > > those apparently otherwise unreachable objects.
> > >
> > > -- ramki
> > >
> > > ----- Original Message -----
> > > From: "Ken--@..." <dragonken@...>
> > > Date: Thursday, October 9, 2008 3:10 am
> > > Subject: Re: CMS collection keep working during holiday
> > > To: hotspot-gc-dev@...
> > >
> > >
>
> --
> View this message in context: http://www.nabble.com/CMS-collection-keep-working-during-holiday-tp19773575p19912471.html
> Sent from the OpenJDK Hotspot Garbage Collection mailing list archive
> at Nabble.com.
>

[Y. Srinivas Ramakrishna]

As the old saying goes, a picture (attached, courtesy of gchisto)
is worth a thousand words (well, actually only about 190 words below,
but still). See how the scavenge times become so much better
following the full gc's? (For some reason gchisto and our
log fixer are unable to fix up and recognise the most dramatic
one far to the right at timestamp 504379.249.

> It so happens that in some cases you can actually clearly see the
> deleterious effect of accumulating perm gen garbage on the performance
> of not only CMS (which, as in your case, had an artifically bloated
> footprint and was running useless cycles), but on scavenges --
> the latter is two-fold: firstly the quasi-immortal (modulo
> mark-compact which reclaims them) class loaders and other class-cohorts
> act as barriers to coalition and tend to fragment the old gen, causing
> much pain to scavenges, which slow down over time; further,
> the dead classes in the perm gen act as "dead roots" that inflates
> the root-scanning time for scavenges and further slows down scavenges.
> In a recent exchange, i think on this list, we saw a nice expample
> of that. We can probably extract a time-series plot of the scavenge
> times from your logs to see if we see a similar trending which
> is often a signature of problems such as these. (Of course similar
> signatures would appear also with some memory leaks, as Tony and Kirk
> suspected earlier.)

-- ramki

[kirk-17]

Hi,

I've got a histogram that includes a number of classes that I've not
seen at the top of a histogram just yet. This is a pre-gc histogram from
the 1.5.0_15. Any thoughts on what might cause these to build up?

      1 Object Histogram:
      2
      3 Size    Count   Class description
      4 -------------------------------------------------------
      5 2009570160      35394   int[]
      6 25703600        237926  char[]
      7 23512384        20129   byte[]
      8 18761568        144582  * ConstMethodKlass   <----
      9 10416360        144582  * MethodKlass            <----
     10 8144800 194428  * SymbolKlass                   <----
     11 7925040 13619   * ConstantPoolKlass            <----
     12 6832800 284700  java.lang.String
     13 5619232 13619   * InstanceKlassKlass            <----
     14 4503280 11914   * ConstantPoolCacheKlass    <----
     15 3498664 37130   java.util.HashMap$Entry[]
     16 3116000 97375   java.util.TreeMap$Entry
     17 3067808 37737   java.lang.Object[]
     18 2498800 31235   java.lang.reflect.Method
     19 2364600 98525   java.util.HashMap$Entry
     20 1683520 42088   org.apache.velocity.runtime.parser.Token
     21 1626552 5532    * MethodDataKlass          <----

Regards,
Kirk Pepperdine

[Y. Srinivas Ramakrishna]

These are class meta-data that live in the perm gen.

-- ramki

----- Original Message -----
From: kirk <kirk.pepperdine@...>
Date: Monday, October 13, 2008 8:56 am
Subject: Re: CMS collection keep working during holiday
Cc: hotspot-gc-dev@...

> Hi,
>
> I've got a histogram that includes a number of classes that I've not
> seen at the top of a histogram just yet. This is a pre-gc histogram
> from
> the 1.5.0_15. Any thoughts on what might cause these to build up?
>
>       1 Object Histogram:
>       2
>       3 Size    Count   Class description
>       4 -------------------------------------------------------
>       5 2009570160      35394   int[]
>       6 25703600        237926  char[]
>       7 23512384        20129   byte[]
>       8 18761568        144582  * ConstMethodKlass   <----
>       9 10416360        144582  * MethodKlass            <----
>      10 8144800 194428  * SymbolKlass                   <----
>      11 7925040 13619   * ConstantPoolKlass            <----
>      12 6832800 284700  java.lang.String
>      13 5619232 13619   * InstanceKlassKlass            <----
>      14 4503280 11914   * ConstantPoolCacheKlass    <----
>      15 3498664 37130   java.util.HashMap$Entry[]
>      16 3116000 97375   java.util.TreeMap$Entry
>      17 3067808 37737   java.lang.Object[]
>      18 2498800 31235   java.lang.reflect.Method
>      19 2364600 98525   java.util.HashMap$Entry
>      20 1683520 42088   org.apache.velocity.runtime.parser.Token
>      21 1626552 5532    * MethodDataKlass          <----
>
> Regards,
> Kirk Pepperdine
>

[kirk-17]

Hi Ramki,

Thanks. Running the default collectors so I'm believing that these
should be collected. These are from the C++ layer?

Regards,
Kirk

Y Srinivas Ramakrishna wrote:

> These are class meta-data that live in the perm gen.
>
> -- ramki
>
> ----- Original Message -----
> From: kirk <kirk.pepperdine@...>
> Date: Monday, October 13, 2008 8:56 am
> Subject: Re: CMS collection keep working during holiday
> Cc: hotspot-gc-dev@...
>
>
>  
>> Hi,
>>
>> I've got a histogram that includes a number of classes that I've not
>> seen at the top of a histogram just yet. This is a pre-gc histogram
>> from
>> the 1.5.0_15. Any thoughts on what might cause these to build up?
>>
>>       1 Object Histogram:
>>       2
>>       3 Size    Count   Class description
>>       4 -------------------------------------------------------
>>       5 2009570160      35394   int[]
>>       6 25703600        237926  char[]
>>       7 23512384        20129   byte[]
>>       8 18761568        144582  * ConstMethodKlass   <----
>>       9 10416360        144582  * MethodKlass            <----
>>      10 8144800 194428  * SymbolKlass                   <----
>>      11 7925040 13619   * ConstantPoolKlass            <----
>>      12 6832800 284700  java.lang.String
>>      13 5619232 13619   * InstanceKlassKlass            <----
>>      14 4503280 11914   * ConstantPoolCacheKlass    <----
>>      15 3498664 37130   java.util.HashMap$Entry[]
>>      16 3116000 97375   java.util.TreeMap$Entry
>>      17 3067808 37737   java.lang.Object[]
>>      18 2498800 31235   java.lang.reflect.Method
>>      19 2364600 98525   java.util.HashMap$Entry
>>      20 1683520 42088   org.apache.velocity.runtime.parser.Token
>>      21 1626552 5532    * MethodDataKlass          <----
>>
>> Regards,
>> Kirk Pepperdine
>>
>>    
>
>  

[Y. Srinivas Ramakrishna]

> Thanks. Running the default collectors so I'm believing that these
> should be collected. These are from the C++ layer?

Sorry, i was not very clear. No, this is from the JVM's representation of
the classes used by the application that the JVM is running.
It's possible that the classes here are in fact being actively
used by your application and/or represent the classes that were
loaded by the system class-loader and will therefore never be unloaded?
(although the total size occupied by them here appears suspiciously
large.) Check "jmap -permstat" for more information; you might also
want to try a more recent jvm perhaps.

best.
-- ramki

>
> Regards,
> Kirk
>
> Y Srinivas Ramakrishna wrote:
> > These are class meta-data that live in the perm gen.
> >
> > -- ramki
> >
> > ----- Original Message -----
> > From: kirk <kirk.pepperdine@...>
> > Date: Monday, October 13, 2008 8:56 am
> > Subject: Re: CMS collection keep working during holiday
> > Cc: hotspot-gc-dev@...
> >
> >
> >  
> >> Hi,
> >>
> >> I've got a histogram that includes a number of classes that I've
> not
> >> seen at the top of a histogram just yet. This is a pre-gc histogram
>
> >> from
> >> the 1.5.0_15. Any thoughts on what might cause these to build up?
> >>
> >>       1 Object Histogram:
> >>       2
> >>       3 Size    Count   Class description
> >>       4 -------------------------------------------------------
> >>       5 2009570160      35394   int[]
> >>       6 25703600        237926  char[]
> >>       7 23512384        20129   byte[]
> >>       8 18761568        144582  * ConstMethodKlass   <----
> >>       9 10416360        144582  * MethodKlass            <----
> >>      10 8144800 194428  * SymbolKlass                   <----
> >>      11 7925040 13619   * ConstantPoolKlass            <----
> >>      12 6832800 284700  java.lang.String
> >>      13 5619232 13619   * InstanceKlassKlass            <----
> >>      14 4503280 11914   * ConstantPoolCacheKlass    <----
> >>      15 3498664 37130   java.util.HashMap$Entry[]
> >>      16 3116000 97375   java.util.TreeMap$Entry
> >>      17 3067808 37737   java.lang.Object[]
> >>      18 2498800 31235   java.lang.reflect.Method
> >>      19 2364600 98525   java.util.HashMap$Entry
> >>      20 1683520 42088   org.apache.velocity.runtime.parser.Token
> >>      21 1626552 5532    * MethodDataKlass          <----
> >>
> >> Regards,
> >> Kirk Pepperdine
> >>
> >>    
> >
> >  
>

[kirk-17]

Hi Ramki,

Yes, the size is suspiciously large which is why I don't suspect the
bootstrap classloader. I'll get a permspace histo. Unfortunately I can't
use the 1.6 as I'm tied in by JBoss. We do have a proper staging
environment which I'm going to move to. I was just trying to get a
characterization of the problem in prod prior to putting a proper heap
profiler to work.

Thanks for you conformation of my suspicions.

Regards,
Kirk

Y Srinivas Ramakrishna wrote:

>> Thanks. Running the default collectors so I'm believing that these
>> should be collected. These are from the C++ layer?
>>    
>
> Sorry, i was not very clear. No, this is from the JVM's representation of
> the classes used by the application that the JVM is running.
> It's possible that the classes here are in fact being actively
> used by your application and/or represent the classes that were
> loaded by the system class-loader and will therefore never be unloaded?
> (although the total size occupied by them here appears suspiciously
> large.) Check "jmap -permstat" for more information; you might also
> want to try a more recent jvm perhaps.
>
> best.
> -- ramki
>
>
>  
>> Regards,
>> Kirk
>>
>> Y Srinivas Ramakrishna wrote:
>>    
>>> These are class meta-data that live in the perm gen.
>>>
>>> -- ramki
>>>
>>> ----- Original Message -----
>>> From: kirk <kirk.pepperdine@...>
>>> Date: Monday, October 13, 2008 8:56 am
>>> Subject: Re: CMS collection keep working during holiday
>>> Cc: hotspot-gc-dev@...
>>>
>>>
>>>  
>>>      
>>>> Hi,
>>>>
>>>> I've got a histogram that includes a number of classes that I've
>>>>        
>> not
>>    
>>>> seen at the top of a histogram just yet. This is a pre-gc histogram
>>>>        
>>>> from
>>>> the 1.5.0_15. Any thoughts on what might cause these to build up?
>>>>
>>>>       1 Object Histogram:
>>>>       2
>>>>       3 Size    Count   Class description
>>>>       4 -------------------------------------------------------
>>>>       5 2009570160      35394   int[]
>>>>       6 25703600        237926  char[]
>>>>       7 23512384        20129   byte[]
>>>>       8 18761568        144582  * ConstMethodKlass   <----
>>>>       9 10416360        144582  * MethodKlass            <----
>>>>      10 8144800 194428  * SymbolKlass                   <----
>>>>      11 7925040 13619   * ConstantPoolKlass            <----
>>>>      12 6832800 284700  java.lang.String
>>>>      13 5619232 13619   * InstanceKlassKlass            <----
>>>>      14 4503280 11914   * ConstantPoolCacheKlass    <----
>>>>      15 3498664 37130   java.util.HashMap$Entry[]
>>>>      16 3116000 97375   java.util.TreeMap$Entry
>>>>      17 3067808 37737   java.lang.Object[]
>>>>      18 2498800 31235   java.lang.reflect.Method
>>>>      19 2364600 98525   java.util.HashMap$Entry
>>>>      20 1683520 42088   org.apache.velocity.runtime.parser.Token
>>>>      21 1626552 5532    * MethodDataKlass          <----
>>>>
>>>> Regards,
>>>> Kirk Pepperdine
>>>>
>>>>    
>>>>        
>>>  
>>>      
>
>