Perplexing GC Time Growth

[Steve Bohne]

Jason,

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.

Normally, local references should be deleted automatically when a native 
method returns to Java.  One explanation for this behavior might involve 
some thread sitting in a native method and generating local references 
for a very long/indefinite amount of time, without returning to Java. 
Is this a possibility?

Thanks,
Steve

> 
> 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
>>>>
> 
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use