objects hanging around after 1st Full GC

[Tony Printezis]

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