G1GC, Java8u40ea, Metaspace questions

[Jon Masamitsu]

On 2/13/2015 10:25 AM, Wolfgang Pedot wrote:
> Thanks for your reply,
>
> I was under the impression that the MetaspaceSize is only used as a 
> starting value for the high-water mark and 
That's correct.

> adjusting it will only change the behaviour at startup. Correct me if 
> I am wrong but after the first collect ergonomics 

If "at startup" includes the  first time the metaspace reaches 
MetaspaceSize, yes that is also correct.

> would take over and adjust that mark according to 
> Min/MaxMetaspaceFreeRatio, right? My problem is that I have to 
Right.

> deal with lots of short lived generated classes and it would be a step 
> back to have the garbage-collector set a low mark right before a 
> class-generation spike and then do a Full-GC before raising it again 
> (Full-GC currently takes ~10sec on the real system). Although with 
> MaxMetaSpaceFreeRation being 70% by default that would probably not 
> happen that often.
>
> As for my first question, it is still not clear to me why Metaspace 
> "capacity" never seemed to reach "commited" during my first tests. I 
> have checked the logs for the current instance and with the higher 
> maximum-setting "capacity" and "commited" actually can get quite close 
> now but both are nowhere near the allowed maximum even after I have 
> driven the JVM into multiple FullGCs by creating classes like crazy. 
> Can I assume that RAM that is not 

You're running on a 32 bit system, right?  Can you run this and let us 
know what comes out.

java  -XX:+UseG1GC -XX:+PrintGCDetails -version

I expect something like

java version "1.9.0-ea"
Java(TM) SE Runtime Environment (build 1.9.0-ea-b10)
Java HotSpot(TM) Server VM (build 25.0-b62, mixed mode)
Heap
  garbage-first heap   total 65536K, used 0K [0xa1400000, 0xa5400000, 
0xe1400000)
   region size 1024K, 1 young (1024K), 0 survivors (0K)
  Metaspace       used 1418K, capacity 2200K, committed 2200K, reserved 
4400K


> "commited" is not actually used by the JVM and can still be used by 
> the OS for filesystem cache and the such?

If not committed, it is not being used by the JVM but the OS might not use
the space for anything else since the memory has been reserved. Depends on
the OS.

>
> Now to my second question:
>
> I was not talking about Full-GC there, what I was referring to is such 
> a log-line:
>
> [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, 
> reason: requested by GC cause, GC cause: Metadata GC Threshold]
>
> this tells me that G1 will trigger a concurrent cycle when the 
> Metaspace threshold is reached and sometimes that leads to classes 
> getting unloaded BEFORE there is a FullGC for the very same reason. I 
> would very much prefer this happening more often and FullGC only being 
> used as a last-resort. Unfortunately most of the time there is a 
> FullGC triggered right after I see the request for a concurrent cycle, 
> this means that I can only benefit from concurrent class unloading if 
> there is enough activity in old-gen to trigger concurrent cycles 
> because of heap-occupation. If G1 would use a lower Metaspace 
> threshold to initiate a concurrent cycle there would be a higher 
> chance for classes to get unloaded without a FullGC even if heap 
> occupation is currently low. That would be similar to what is going on 
> in the heap, concurrent cycles are started before the limit is reached 
> and a FullGC is required. Am I wrong here?

I think you are right again.    One explanation for what you are seeing 
is that
the high-water-mark has grown too high.    The concurrent collection for
metadata has been started but there isn't enough metadata available for
the needed allocations (runs out and then the full GC happens).  I don't
understand yet why you have so much metaspace reserved but not
committed yet so don't know if this is actually what you are seeing.

Jon

>
> Wolfgang
>
>
>
> Am 13.02.2015 18:20, schrieb Yu Zhang:
>> Wolfgang,
>>
>> Please see my comments in line.
>> Thanks,
>> Jenny
>> On 2/13/2015 5:36 AM, Wolfgang Pedot wrote:
>>> Hello,
>>>
>>> my last mail regarding this topic seems to have been lost somewhere 
>>> but thats not really a problem because my questions have changed:
>>>
>>> I am currently evaluation 8u40 early-access (b21 and b23) for an 
>>> application server which, unfortunately, generates a fair amount of 
>>> short-lived dynamic classes. So far it runs on 7u67 and has enough 
>>> PermGen space to survive most days with 1 FullGC to get rid of the 
>>> classes. This situation is somewhat acceptable but I am really 
>>> looking forward to not requiring FullGCs for class unloading, hence 
>>> my tests with 8u40ea.
>>> I am testing on a smaller system with much less headroom in PermGen 
>>> and as a first shot I just renamed MaxPermSize to MaxMetaspaceSize 
>>> and everything looked OK at first, classes where unloaded without 
>>> FullGCs and I was happy. When the Metaspace baseline-usage grew I 
>>> noticed that there where quite some FullGCs after all and when 
>>> looking closer I noticed that they came in pairs:
>>>
>>> 276129.049: [Full GC (Metadata GC Threshold) 
>>> 2015-02-05T17:03:04.509+0100: 276129.049: [GC 
>>> concurrent-root-region-scan-end, 0.0001449 secs]
>>> 2015-02-05T17:03:04.509+0100: 276129.049: [GC concurrent-mark-start]
>>>   492M->476M(904M), 1.5020455 secs]
>>>     [Eden: 0.0B(336.0M)->0.0B(352.0M) Survivors: 16.0M->0.0B Heap: 
>>> 492.2M(904.0M)->476.4M(904.0M)], [Metaspace: 
>>> 183332K->183332K(1247232K)]
>>>   [Times: user=2.74 sys=0.01, real=1.50 secs]
>>> 2015-02-05T17:03:06.011+0100: 276130.551: [Full GC (Last ditch 
>>> collection)  476M->468M(904M), 1.4614149 secs]
>>>     [Eden: 0.0B(352.0M)->0.0B(360.0M) Survivors: 0.0B->0.0B Heap: 
>>> 476.4M(904.0M)->468.0M(904.0M)], [Metaspace: 
>>> 183332K->178688K(1247232K)]
>>>   [Times: user=2.62 sys=0.01, real=1.46 secs]
>>>
>>> MaxMetaspaceSize was set to 228M at the time so it was not 
>>> completely full yet the JVM threw in a "Last ditch collection" after 
>>> every (quite frequent) FullGC to desperately try and free some 
>>> Metaspace.
>>> I even got to the point where the JVM threw OOME:Metaspace errors 
>>> even though according to the numbers Metaspace was nowhere near full 
>>> (different settings though).
>> MaxMetaspaceSize is the maximum size Metadata space can expand to.  
>> GC will start with metadata space defined by MetaspaceSize, then 
>> expand/shrink it.  When it needs to expand it, a 'Metadata GC 
>> Threshold' full gc is called.  To avoid this kind of full gc, you can 
>> increase MetaspaceSize.
>>
>> In jdk8u40, ClassUnloadingWithConcurrentMark(default true) so that 
>> the classes can be unloaded with concurrent marking.  This will 
>> reduce the chance of running into Metadata GC Threshold' full gc
>>
>>> After banging my head against various settings regarding Metaspace I 
>>> decided to run some worst-case tests on my laptop with different 
>>> MaxMetaspaceSize-values (no other metaspace related settings). My 
>>> test generates lots of classes while causing only minor increases in 
>>> old-gen so the JVM runs into FullGC (Metaspace threshold) 
>>> consistently. I discovered that the reported Metaspace-Size in the 
>>> gclog (and jconsole) never actually reaches the configured maximum 
>>> but instead tops out at about 85% of that value. "Commited" will be 
>>> the Maxsize but "capacity" never goes that high and since my 
>>> test-system did not have enough headroom to cover that it was 
>>> collecting because of Metaspace way to often.
>>>
>>> This brings me to my first question: What is the reason why the JVM 
>>> (appearantly) does not use the whole space it is allowed to use?  Is 
>>> other stuff stored in there but not reported or is there some kind 
>>> of overhead?
>>>
>>> After giving the test-system more headroom it appears to work OK but 
>>> it always takes a couple of days use before Metaspace-baseline evens 
>>> out so I will see next week if that did the trick, I dont really 
>>> want to go "no limit".
>>>
>>> Now a more general question:
>>> I noticed that G1 also triggers a concurrent marking cycle because 
>>> of "Metaspace threshold", is it using the same threshold that would 
>>> also trigger a FullGC or is it slightly lower? Is that treshold 
>>> visible somewhere?
>>> The reason I am asking is that I want to keep FullGCs down to a 
>>> minimum so if the class count rises reasonably slow even without 
>>> causing much oldgen-increase should the concurrent cycle be 
>>> triggered before the JVM throws in a FullGC most of the time?
>> You are talking about Full GC caused by 2 reasons:
>>
>>  *
>>     Metaspace threshold: we can avoid this my increasing 
>> MetadataspaceSize
>>
>>   * Allocation Failure: usually this happens after a few 'to-space
>>     exhausted'.  I think this is not what you see in your log. A lot
>>     of time this is caused by poor tuning.  The marking cycles are
>>     triggered after initial marking.  And when initial marking is
>>     triggered, is decided by InitiatingHeapOccupancyPercent
>>
>>> Quite a long Mail for two questions, any hints would be greatly 
>>> appreciated!
>>>
>>> Wolfgang
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>
>
>