Java GC running very frequently after minimal allocations

Question

I'm writing a realtime game for android, and as such I'd like to minimize allocation/garbage collection as much as possible as recommended in androids "Designing for Performance" developer guide.

I've got a very simple game that's not using much memory (<2-3% of heap according to hprof heap dump), but my concurrent gc runs like clockwork every 7 seconds, always freeing about 1MB of memory. My game is completely paused and not doing anything interesting, and running the allocation tracker for 5 seconds shows very few allocations. This is the entirety of the allocation tracker dump after being open for a few seconds, which looks to account for less than 1kb of allocations (mostly just dalvik stuff and my lock's lock/unlock method).

19  24  byte[]  5   dalvik.system.NativeStart   run 
18  12  java.lang.Integer   5   java.lang.Integer   valueOf 
17  24  org.apache.harmony.dalvik.ddmc.Chunk    5   org.apache.harmony.dalvik.ddmc.DdmServer    dispatch    
16  17  byte[]  5   android.ddm.DdmHandleHeap   handleREAQ  
15  24  org.apache.harmony.dalvik.ddmc.Chunk    5   android.ddm.DdmHandleHeap   handleREAQ  
14  28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
13  28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
12  28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
11  28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
10  28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
9   28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
8   28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
7   28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
6   28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
5   28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
4   28  java.util.concurrent.locks.AbstractQueuedSynchronizer$Node  10  java.util.concurrent.locks.AbstractQueuedSynchronizer   addWaiter   
3   24  byte[]  5   dalvik.system.NativeStart   run 
2   12  java.lang.Integer   5   java.lang.Integer   valueOf 
1   24  org.apache.harmony.dalvik.ddmc.Chunk    5   org.apache.harmony.dalvik.ddmc.DdmServer    dispatch    

Yet despite all this, I continually see about 1MB of collection every few seconds:

03-09 21:41:56.665: D/dalvikvm(4210): GC_CONCURRENT freed 934K, 58% free 3069K/7175K, external 2847K/3550K, paused 3ms+2ms
03-09 21:42:03.685: D/dalvikvm(4210): GC_CONCURRENT freed 937K, 58% free 3069K/7175K, external 2847K/3550K, paused 3ms+1ms
03-09 21:42:10.705: D/dalvikvm(4210): GC_CONCURRENT freed 937K, 58% free 3069K/7175K, external 2847K/3550K, paused 5ms+2ms
03-09 21:42:17.715: D/dalvikvm(4210): GC_CONCURRENT freed 934K, 58% free 3069K/7175K, external 2847K/3550K, paused 3ms+1ms
03-09 21:42:24.725: D/dalvikvm(4210): GC_CONCURRENT freed 934K, 58% free 3069K/7175K, external 2847K/3550K, paused 2ms+3ms

I know its not much time, though I'd not want to have 10 milliseconds randomly stolen from one of my frames if I can avoid it. My question is if I don't see anything in the allocation tracker, just what could be allocating so much memory in just a few seconds? I don't think its anything on the background of the phone, because as soon as I exit the game I don't see GC anymore (or very rarely).

My rendering thread uses GLSurfaceView which is pretty much the only thing running while its paused, but I'm just stumped on where my memory's going.

Any thoughts are appreciated.

Answer 1

Ok, I found the leak. Turns out I was running clone unnecessarily on a float array about 50 times per frame, but what really threw me off was that this doesn't appear in the allocation tracker.

A little more research showed me this thread, which seems to claim that there's an android bug where array.clone() operations don't show up in the allocation tracker.

Frustrated it took me this long to find it, but at least now I'm only collecting <1kb per second.