Perplexing GC Time Growth

[Jason Vasquez]

Thought you may be interested in the latest GC log -- this is just  
past the 7.5 hour mark, GC times are still holding steady at 20ms  
(grand improvement)   Perm Gen sweep/Class unloading is enabled here  
as well, btw.  There appears thre might be a remaining small leak  
troubling the old gen a bit, but it's growth is relatively minor, I'll  
have a look there next now that the other noise has subsided :)

-------------- next part --------------
A non-text attachment was scrubbed...
Name: garbage.log.gz
Type: application/x-gzip
Size: 13957 bytes
Desc: not available
Url : http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20080109/4d96201d/attachment.bin 
-------------- next part --------------



Anyway, thanks again for your consideration of this issue, seems as if  
it might be in hand now.
-jason


On Jan 8, 2008, at 11:16 , Jason Vasquez wrote:

> Well, interesting finds yesterday --
>
> You had me thinking about gcroots again -- I inspected the gc roots  
> via jhat after a 24 hour run of the application, and noticed some  
> surprising results.  The jhat output was quite large and ended up  
> crashing the browser after it consumed >2gb RAM :)   dumped it out  
> via curl, and stopped after the HTML output capped 350MB over the  
> slow VPN link.   Appears with the limited output, there were  
> >1.5million JNI Local References hanging around. (and likely more if  
> I had been able to obtain the full output)
>
> Looks like the count sits idle at about 5 local refs, and grows very  
> rapidly during normal running of the application (in tens of  
> thousands after a couple minutes)   I peppered the native code with  
> DeleteLocalRef directives anywhere a local reference was declared,  
> and the number of JNI local refs now stays steady at 52-53 during  
> full load. (!)   The JNI documentation seems to indicate that I  
> shouldn't need to do that for these type of references, but in any  
> case, that is an extreme difference.
>
> This makes sense for the linear increase in GC times, since the  
> number of JNI Local Refs (and, by extension, gc roots) was likely  
> growing at a quite rapid and liner pace.
>
> I've started a new run in our load test environment now, with high  
> hopes of success this time, I'll let you know how it turns out.  I  
> had temporarily disabled the PermGen sweep at the beginning of the  
> test, and am seeing some very slow growth in the perm gen, I might  
> still need that flag back before we're all done, but this is a good  
> start.
>
> Thanks for your assistance - I'm hoping for the best,
> -jaosn
>
>
> On Jan 5, 2008, at 09:46 , Jason Vasquez wrote:
>
>> Hi Ramki,
>>
>> Sorry for the delay, I'm on vacation visiting some family over a  
>> long weekend, trying not to draw the wrath of my wife for stealing  
>> time away hopping on the VPN to check things out :)
>>
>> Anyway, I've attached the latest garbage log, unfortunately, it  
>> doesn't seem to have changed things much (although I can see that  
>> the flags are now taking affect)
>>
>> -jason
>>
>> <garbage.log.gz>
>>
>>
>>
>> On Jan 4, 2008, at 14:54 , Y Srinivas Ramakrishna wrote:
>>
>>> Hi Jason -- did you get a chance to check what happens to scavenge
>>> times with both the class unloading options specified as stated  
>>> below.
>>>
>>> thanks!
>>> -- ramki
>>>
>>> ----- Original Message -----
>>> From: Y.S.Ramakrishna at Sun.COM
>>> Date: Thursday, January 3, 2008 4:10 pm
>>> Subject: Re: Perplexing GC Time Growth
>>> To: Jason Vasquez <jason at mugfu.com>
>>> Cc: hotspot-gc-use at openjdk.java.net
>>>
>>>
>>>> Hi Jason --
>>>>
>>>> Y.S.Ramakrishna at Sun.COM wrote:
>>>> ...
>>>>> While we think of potential reasons for this, or mull over
>>>>> appropriate sensors that can lay bare the root cause here,
>>>>> could you, on a quick hunch, do a quick experiment and tell
>>>>> me if adding the options -XX:+CMSClassUnloadingEnabled makes
>>>>> any difference to the observations above. [Does your application
>>>>> do lots of class loading or reflection or string interning?]
>>>>
>>>> I think i screwed up a bit here. I was assuming you were using
>>>> the (newest) OpenJDK build. As it happens, in 6u3 and older
>>>> you need to specify both +CMSClassUnloadingEnabled _and_
>>>> +CMSPermGenSweepingEnabled, else you do not get the desired effect.
>>>> Sorry this was fixed after 6u3, so the additional flag did not
>>>> do anything in your case.
>>>>
>>>> Let me know if the additional flag (please use both) made
>>>> a difference, and apologies for the bad user interface here
>>>> (set right as of 6u4 and in OpenJDK).
>>>>
>>>> -- ramki
>>>>
>>>>>
>>>>
>>
>