Decoding Android GC Logs

Foreword

Link to the original English version. If you find any issues with this article, please point them out so they can be corrected in time. Below is the translation.

Android is designed for mobile devices, so developers should always keep an eye on the RAM (Random-Access Memory) consumed by their apps. Although Dalvik and ART perform routine garbage collection (GC), it doesn't mean developers can ignore the app's memory usage (when, where, and how much memory was allocated/released). To ensure a stable user experience and allow the system to switch between multiple apps quickly, it is important that an app does not consume unnecessary memory when the user is not interacting with it.

P.S. Dalvik (Android-specific JVM), ART (Android Runtime). ART was introduced in Android 4.4; before that, it was Dalvik.

Even if all best practices for managing app memory are followed during development (as developers should), object leaks or other memory bugs may still occur. The only reliable way to minimize an app's memory footprint is to analyze its memory usage with tools. This guide will detail how to do that.

Interpreting Log Messages

The easiest way to view an app's memory usage is through runtime log messages. After a GC is executed, a piece of information is output to Logcat. Logcat output can be viewed in the Device Monitor or directly within an IDE such as Android Studio.

Dalvik Log Messages

In Dalvik (not ART) mode, every GC outputs the following information to Logcat:

D/dalvikvm: <GC_Reason> <Amount_freed>, <Heap_stats>, <External_memory_stats>, <Pause_time>

Example:

D/dalvikvm( 9050): GC_CONCURRENT freed 2049K, 65% free 3571K/9991K, external 4703K/5261K, paused 2ms+2ms

GC Reason

What triggered the GC and what type of garbage collection it is. Possible values include:

• GC_CONCURRENT

A concurrent GC triggered by the heap starting to fill up.

• GC_FOR_MALLOC

The heap is full, and the app attempted to allocate memory, so the system had to stop the app and reclaim memory, resulting in a failed memory allocation.

• GC_HPROF_DUMP_HEAP

A GC triggered by a request to create an HPROF file for heap analysis.

P.S. An HPROF file describes heap usage, similar to Chrome's heapsnapshot file.

• GC_EXPLICIT

An explicit GC, such as calling gc() (this should be avoided; trust the GC to run automatically when needed).

• GC_EXTERNAL_ALLOC

A GC caused by external memory allocations (such as pixel data stored in native memory or NIO byte buffers). This only appears in API 10 and lower (in newer versions, everything is allocated in the Dalvik heap).

Amount freed

The amount of memory reclaimed by this GC.

Heap stats

Percentage of free memory in the heap, and [used memory size]/[total heap size].

External memory stats

External memory statistics.

In API 10 and lower, externally allocated memory, and [allocated memory size]/[GC threshold].

P.S. GC is performed when the GC threshold is reached.

Pause time

The larger the heap, the more pause times are required. Concurrent GC (GC Reason: GC_CONCURRENT) pause times are split into two parts: one at the start of the GC and another at the end.

Note these log messages and focus on the heap stats (e.g., 3571K/9991K). If it continues to grow, a memory leak likely exists.

ART Log Messages

Unlike Dalvik, ART does not log GCs that were not explicitly requested unless they are determined to be slow. More precisely, the condition is a GC pause exceeding 5ms or a GC duration exceeding 100ms. If the app is not in a perceptible pause state, the GC will not be judged as slow, though explicit GCs will still be logged.

ART's GC logs contain the following information:

I/art: <GC_Reason> <GC_Name> <Objects_freed>(<Size_freed>) AllocSpace Objects, <Large_objects_freed>(<Large_object_size_freed>) <Heap_stats> LOS objects, <Pause_time(s)>

Example:

I/art : Explicit concurrent mark sweep GC freed 104710(7MB) AllocSpace objects, 21(416KB) LOS objects, 33% free, 25MB/38MB, paused 1.230ms total 67.216ms

GC Reason

What triggered the GC and what type of garbage collection it is. Possible values include:

• Concurrent

A concurrent GC that does not suspend app threads. This GC runs in a background thread and does not block memory allocations.

• Alloc

GC was initiated because the app requested memory allocation while the heap was full. In this case, the GC is executed in the current thread (the thread requesting memory).

• Explicit

GC was explicitly requested by the app, for example, by calling System.gc() or runtime.gc(). Like Dalvik, ART suggests trusting the GC and avoiding explicit GC requests as much as possible. Explicit GCs are discouraged because they block the current thread and cause unnecessary CPU cycles. If GC causes other threads to be preempted, explicit GC can also cause jank.

P.S. Jank refers to a situation where after the nth frame is drawn, the (n+1)th frame should be drawn, but because the CPU was preempted and data wasn't ready, the nth frame has to be displayed again, and the (n+1)th frame is only displayed at the next draw.

• NativeAlloc

GC caused by native memory pressure from native allocations, such as Bitmap or RenderScript objects.

• CollectorTransition

GC caused by a heap transition, resulting from dynamically switching GC algorithms at runtime. The collector transition process includes copying all objects from a free-list backed space to a bump pointer space (or vice versa). Currently, collector transitions only occur on low-RAM devices when the app changes its run state, such as from a perceptible pause state to a non-perceptible pause state (or vice versa).

• HomogeneousSpaceCompact

Homogeneous space compaction is the merging of a free-list space with another free-list space, often occurring when the app enters an imperceptible pause state. The main reasons for this are to reduce RAM usage and defragment the heap.

• DisableMovingGc

Not a real GC reason, but a GC that is defragmenting is blocked by GetPrimitiveArrayCritical. Generally, it is strongly recommended to avoid using GetPrimitiveArrayCritical because it restricts collector transitions.

• HeapTrim

Not a real GC reason, but the GC is blocked until heap trimming finishes.

GC Name

ART has several different types of GC:

• Concurrent mark sweep (CMS)

A whole-heap garbage collector responsible for collecting and freeing all spaces except for the image.

• Concurrent partial mark sweep

Nearly a whole-heap garbage collector, responsible for collecting all spaces except for the image and zygote.

• Concurrent sticky mark sweep

A generational garbage collector responsible only for freeing objects allocated since the last GC. This GC runs more frequently than whole-heap or partial mark sweeps because it is faster and has shorter pauses.

• Marksweep + semispace

A non-concurrent GC used for copying heap transitions and homogeneous space compaction (used to defragment the heap).

Objects freed

The number of objects reclaimed by this GC from the non-large object space.

Size freed

The number of bytes reclaimed by this GC from the non-large object space.

Large objects freed

The number of objects reclaimed by this GC from the large object space.

Large object size freed

The number of bytes reclaimed by this GC from the large object space.

Heap stats

Percentage of free space and [used memory size]/[total heap size].

Pause times

Generally, when GC runs, the pause time is proportional to the number of modified object references. Currently, ART CMS GC pauses only once at the end of the GC. GC transitions involve a long pause, which is the main factor in GC time consumption.

If you see a lot of GC information in Logcat, find the heap stats (e.g., 25MB/38MB). If it continues to grow and never decreases, a memory leak may exist. If the GC reason is Alloc, it means the heap is almost full and an OOM is imminent.