OutOfMemoryError for small allocation when there seems to be loads of heap space available

Question

I'm testing my app on an HTC Sensation OS 4.0.3. I'm confused why I'm hitting OutOfMemoryErrors in some scenarios, when it appears that I have plenty of memory available.

For example, in this case I had been using my app fine. I left it unattended for ~5 minutes and confirmed that the app had shut down its network connection and processing threads. When I turned the screen back on a few minutes later I immediately saw a crash popup appear.

I've tried to list the logs that seem like they might be important below.

grep "GC_\|memalloc\|OutOfMemoryError" ~/trace.txt

This specific case shows a 130KB byte buffer allocation failing, when apparently there is 40MB free heap space. I've seen plenty of other places where a small allocation fails too, most commonly in setContentView in onCreate, or some other small UI operation.

10-05 00:26:32.299 32478 32481 D dalvikvm: GC_CONCURRENT freed 4032K, 73% free 13737K/49187K, paused 3ms+28ms
10-05 00:26:38.105 32478 32481 D dalvikvm: GC_CONCURRENT freed 3812K, 73% free 13481K/49187K, paused 4ms+27ms
10-05 00:26:41.698 32478 32481 D dalvikvm: GC_CONCURRENT freed 3927K, 74% free 13122K/49187K, paused 3ms+26ms
10-05 00:26:45.802 32478 32481 D dalvikvm: GC_CONCURRENT freed 3572K, 74% free 12999K/49187K, paused 3ms+27ms
10-05 00:26:48.365 32478 32481 D dalvikvm: GC_CONCURRENT freed 3563K, 74% free 12844K/49187K, paused 3ms+26ms
10-05 00:26:53.069 32478 32481 D dalvikvm: GC_CONCURRENT freed 3506K, 75% free 12675K/49187K, paused 4ms+55ms
10-05 00:26:57.363 32478 32481 D dalvikvm: GC_CONCURRENT freed 3672K, 75% free 12303K/49187K, paused 3ms+25ms
10-05 00:27:01.447 32478 32481 D dalvikvm: GC_CONCURRENT freed 3344K, 76% free 12180K/49187K, paused 3ms+24ms
10-05 00:27:05.121 32478 32481 D dalvikvm: GC_CONCURRENT freed 3212K, 76% free 12034K/49187K, paused 4ms+69ms
10-05 00:27:10.426 32478 32481 D dalvikvm: GC_CONCURRENT freed 3267K, 76% free 11813K/49187K, paused 4ms+40ms
10-05 00:27:14.340 32478 32481 D dalvikvm: GC_CONCURRENT freed 3184K, 77% free 11578K/49187K, paused 3ms+41ms

At this point the app shuts down its various threads.  

10-05 00:35:52.545   249   410 D dalvikvm: GC_EXPLICIT freed 3223K, 50% free 17332K/34531K, paused 4ms+14ms
10-05 00:38:54.633 32478 32478 D dalvikvm: GC_FOR_ALLOC freed 2627K, 78% free 10904K/49187K, paused 113ms
10-05 00:38:54.633 32478 32478 I dalvikvm-heap: Forcing collection of SoftReferences for 131102-byte allocation
10-05 00:38:54.733 32478 32478 D dalvikvm: GC_BEFORE_OOM freed 5K, 78% free 10899K/49187K, paused 97ms
10-05 00:38:54.733 32478 32478 E dalvikvm-heap: Out of memory on a 131102-byte allocation.
10-05 00:38:54.733 32478 32478 I dalvikvm: "main" prio=5 tid=1 RUNNABLE
10-05 00:38:54.733 32478 32478 I dalvikvm:   | group="main" sCount=0 dsCount=0 obj=0x40ad3490 self=0x40f9d0
10-05 00:38:54.733 32478 32478 I dalvikvm:   | sysTid=32478 nice=0 sched=0/0 cgrp=default handle=1074746568
10-05 00:38:54.733 32478 32478 I dalvikvm:   | schedstat=( 0 0 0 ) utm=4527 stm=381 core=1
10-05 00:38:54.733 32478 32478 I dalvikvm:   at dalvik.system.VMRuntime.newNonMovableArray(Native Method)
10-05 00:38:54.733 32478 32478 I dalvikvm:   at java.nio.MemoryBlock.allocate(MemoryBlock.java:126)
10-05 00:38:54.733 32478 32478 I dalvikvm:   at java.nio.ReadWriteDirectByteBuffer.<init>(ReadWriteDirectByteBuffer.java:46)
10-05 00:38:54.733 32478 32478 I dalvikvm:   at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:68)
10-05 00:38:54.733 32478 32478 I dalvikvm:   at de.tavendo.autobahn.WebSocketReader.<init>(WebSocketReader.java:98)
<snip>
10-05 00:38:54.743 32478 32478 I dalvikvm: 
10-05 00:38:54.743 32478 32478 E dalvikvm: Out of memory: Heap Size=49187KB, Allocated=10899KB, Limit=49152KB
10-05 00:38:54.743 32478 32478 E dalvikvm: Extra info: Footprint=49187KB, Allowed Footprint=49187KB, Trimmed=32296KB
10-05 00:38:54.743 32478 32478 W dalvikvm: threadid=1: thread exiting with uncaught exception (group=0x40ad2228)
10-05 00:38:54.953   249   279 D memalloc: /dev/pmem: Unmapping buffer base:0x5aea5000 size:16502784 offset:14483456
10-05 00:38:54.953   249   279 D memalloc: /dev/pmem: Unmapping buffer base:0x59a63000 size:6197248 offset:4177920
10-05 00:38:54.963   112 24561 D memalloc: /dev/pmem: Freeing buffer base:0x4259d000 size:2019328 offset:4177920 fd:38
10-05 00:38:55.124 24504 24504 D dalvikvm: GC_EXPLICIT freed 367K, 41% free 3128K/5219K, paused 2ms+6ms
10-05 00:38:55.234   112   169 D memalloc: /dev/pmem: Freeing buffer base:0x42f71000 size:2019328 offset:14483456 fd:29
10-05 00:38:55.574 24504 24504 D dalvikvm: GC_EXPLICIT freed 18K, 41% free 3114K/5219K, paused 2ms+3ms
10-05 00:38:55.804 32478 32478 E Crittercism: java.lang.OutOfMemoryError: (Heap Size=49187KB, Allocated=10899KB)
10-05 00:38:56.305 32478 32481 D dalvikvm: GC_CONCURRENT freed 2736K, 78% free 10851K/49187K, paused 3ms+8ms
10-05 00:38:57.256 32478  1947 D dalvikvm: JIT code cache reset in 2 ms (1048548 bytes 3/0)
10-05 00:38:57.266 32478  1947 D dalvikvm: GC_FOR_ALLOC freed 901K, 78% free 10825K/49187K, paused 80ms
10-05 00:38:57.286 32478 32478 E AndroidRuntime: java.lang.OutOfMemoryError: (Heap Size=49187KB, Allocated=10899KB)

I'm struggling to make sense of these logs - can anybody explain why the crash is happening?

I've read that memory fragmentation can cause allocations to fail even when overall there should be enough memory. Is there a way to confirm if that is the case, and if so, what can I do to cope with this scenario?

The GC_CONCURRENT logs seem to suggest my code is doing a lot of allocations and deallocations, which might support the memory fragmentation theory.

• My app does download a lot of data at certain times, e.g. for a huge account it could be 30-40MB on first time login.
• We also do a lot with images which would add to that total. FYI, we use Volley for our image loading, and have an in-memory (1/8th limit of available memory for this) and a disk cache to avoid repeatedly downloading from the network.

I know my question is similar to this one, but I don't think I need advice on bitmap handling as I am on OS 4.0, so all the bitmap data is visible in the normal heap (i.e. it should already be included in the GC_ log line totals).

Answer 1

It turns out that the underlying cause was a bad memory leak due to using View.setTag(int, java.lang.Object) to hold Views (following the ViewHolder pattern).

On OS 2.3 devices, known Android issue 18273 causes these memory leaks.

The workaround is to use View.setTag(java.lang.Object) instead.

Answer 2

As you can see, the out of memory happens on " java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:68)".

and according to this page:

Direct buffers are optimal for I/O, but they may be more expensive to create than nondirect byte buffers. The memory used by direct buffers is allocated by calling through to native, operating system-specific code, bypassing the standard JVM heap. Setting up and tearing down direct buffers could be significantly more expensive than heap-resident buffers, depending on the host operating system and JVM implementation. The memory-storage areas of direct buffers are not subject to garbage collection because they are outside the standard JVM heap.

So this answers your question that the allocation is not on Java Heap, but some OS memory space.

You may want to relook at your websocket library; or, did you forget to properly close those readers?