objects hanging around after 1st Full GC

[Y. Srinivas Ramakrishna]

What Tony said; if on a post-6.0 JVM, you might try the additional 
option -XX:+PrintReferenceGC for more detail on
#refs etc.

-- ramki

Tony Printezis wrote:
> Shane,
>
> 99.9% of the time this is called by finalization. If there are a lot 
> of finalizable objects that retain a lot of space, then the first Full 
> GC will process them and add them to the finalization queue (but still 
> retain what' reachable from them). Then, after the finalization queue 
> has been processed, the second Full GC will actually reclaim the space.
>
> Do you (or a library that you're using) rely heavily on finalizers?
>
> Tony
>
> Shane Cox wrote:
>> I'm observing a strange pattern in my GC logs:  the first Full 
>> collection doesn't reclaim much space, then the second Full 
>> collection reclaims a large percentage of Tenured space.  This 
>> pattern repeats itself over and over again.  Here is an excerpt from 
>> my GC logs:
>>
>> First Full GC only reclaims 142,813K:
>> 910.866: [GC [PSYoungGen: 123712K->5136K(124544K)] 
>> 1168575K->1051327K(1173120K), 0.0112247 secs] [Times: user=0.04 
>> sys=0.00, real=0.01 secs]
>> 911.139: [GC [PSYoungGen: 123152K->3976K(124608K)] 
>> 1169343K->1051797K(1173184K), 0.0108060 secs] [Times: user=0.04 
>> sys=0.01, real=0.01 secs]
>> 911.150: [Full GC [PSYoungGen: 3976K->0K(124608K)] [PSOldGen: 
>> 1047821K->905008K(1048576K)] 1051797K->905008K(1173184K) [PSPermGen: 
>> 26536K->26536K(53248K)], 2.1919067 secs] [Times: user=2.20 sys=0.00, 
>> real=2.19 secs]
>> 913.640: [GC [PSYoungGen: 118144K->6456K(124608K)] 
>> 1023152K->918339K(1173184K), 0.0300898 secs] [Times: user=0.11 
>> sys=0.00, real=0.03 secs]
>> 913.881: [GC [PSYoungGen: 124600K->6464K(113088K)] 
>> 1036483K->926045K(1161664K), 0.0242545 secs] [Times: user=0.09 
>> sys=0.01, real=0.02 secs]
>>
>> Second Full GC reclaims 796,079K:
>> 933.943: [GC [PSYoungGen: 123280K->4736K(124992K)] 
>> 1167463K->1049778K(1173568K), 0.0099996 secs] [Times: user=0.04 
>> sys=0.00, real=0.01 secs]
>> 934.247: [GC [PSYoungGen: 123520K->4240K(124864K)] 
>> 1168562K->1050930K(1173440K), 0.0099813 secs] [Times: user=0.04 
>> sys=0.00, real=0.01 secs]
>> 934.258: [Full GC [PSYoungGen: 4240K->0K(124864K)] [PSOldGen: 
>> 1046690K->250611K(1048576K)] 1050930K->250611K(1173440K) [PSPermGen: 
>> 26537K->26537K(61440K)], 1.0611080 secs] [Times: user=1.07 sys=0.01, 
>> real=1.06 secs]
>> 935.516: [GC [PSYoungGen: 118784K->6073K(122816K)] 
>> 369395K->258744K(1171392K), 0.0122732 secs] [Times: user=0.05 
>> sys=0.00, real=0.01 secs]
>> 935.704: [GC [PSYoungGen: 122809K->7164K(123904K)] 
>> 375480K->262140K(1172480K), 0.0124191 secs] [Times: user=0.05 
>> sys=0.01, real=0.01 secs]
>>
>> Then the pattern repeats.
>>
>>
>> It's as if many of the objects require two Full GCs in order to be 
>> reclaimed.  Any idea what's going on or how to further investigate 
>> the cause of this behavior?
>>
>> Thanks