Android Dalvik and ART GC(Garbage Collection) logs Analysis

Hello Guys!!! Hope you all are doing well.!!!!!!

Today I am going to discuss GC logs analysis in android. In my previous blog we have discuss android general log analysis. But today topic is concentrated on GC log analysis.
Memory utilization in Android device(let say mobile phone device) is utterly important topic from the beginning of time. Now a day We have high end mobile phone with much memory(RAM) compare to initial day. But still Memory utilization on the mobile app has a significant impact on the customer experience.

Let assume If any app creates a lot of objects during uses, then Garbage Collection (GC) process will be triggered frequently to evict unused objects. As we know Garbage Collection is an automatic process in Android/Java to free-up unused memory, however, frequent Garbage Collection consumes a lot of CPU + it will also pause the app. Frequent pauses can junk the app (i.e. stuttering, juddering, or halting).
Whenever a GC event runs, a log line is printed in the run-time log messages. So by closely monitoring run-time logs or say collected logs file we can understand how many objects by an app is creating, how frequently Garbage collection is triggered, how much time it takes to complete, how much memory is reclaimed after every event.
GC log line format varies based on whether app runs on Dalvik VM or Android Run Time (ART).This is how a typical ART GC log line will look:-

1                                                         2                                                         3

07-01 16:00:44.690: I/art(801): Explicit concurrent mark sweep GC freed 65595(3MB) 

                                     4                                                      5                                    6

AllocSpace objects, 9(4MB) LOS objects, 34% free, 38MB/58MB, paused 1.195ms total 

    7

87.219ms

#	Field	Value	Description
1	Timestamp	07-01 16:00:44.690	Timestamp at which this Garbage Collection event ran
2	GC Reason	Explicit	Reason why Garbage Collection event was triggered.‘Explicit’ indicates that garbage collection was explicitly requested by an app, for example, by calling gc() or gc(). Please refer Below for different types of GC Reasons.
3	GC Name	concurrent mark sweep	ART has various different GCs which can get run. In this case, ‘Concurrent Mark Sweep’ indicates – a whole heap collector which frees collects all spaces other than the image space.  Please refer below for different types of GC Names.
4	Objects freed	65595(3MB)	Amount of objects garbage collected from non-large objects space. Totally 65595 unique objects, whose cumulative size of 3mb is garbage collected (i.e. freed) in this event.
5	Large objects freed	9(4MB)	Amount of objects garbage collected from Large objects space. Totally 9 unique objects, whose cumulative size of 4mb is garbage collected (i.e. freed)
6	Heap usage	38MB/58MB	38mb of objects is alive after this particular GC event. Total allocated heap size for this application is 58mb.
7	GC Pause Time	1.195ms	During certain phases of GC event, the application is paused. In this GC event, pause time is 1.195ms. During pause time, application freezes. One should target for low pause time.
8	GC Total Time	87.219ms	Amount of time this GC event took to complete. It includes the GC Pause time as well.

GC Reason
What triggered the GC and what kind of collection it is.
Concurrent
A concurrent GC that does not suspend app threads. This GC runs in a background thread and does not prevent allocations.
Alloc
The GC was initiated because your app attempted to allocate memory when your heap was already full. In this case, the garbage collection occurred in the allocating thread.
Explicit
The garbage collection was explicitly requested by an app, for example, by calling gc() or gc(). Like Dalvik, in ART the best practice is that you trust the GC and avoid requesting explicit GCs, if possible. Explicit GCs are discouraged because they block the allocating thread and unnecessarily waste CPU cycles. Explicit GCs could also cause jank (stuttering, juddering, or halting in the app) if they cause other threads to get preempted.
NativeAlloc
The collection was caused by native memory pressure from native allocations such as Bitmaps or RenderScript allocation objects.
CollectorTransition
The collection was caused by a heap transition; this is caused by changing the GC strategy at run time (such as when the app changes between pause perceptible states). Collector transitions consist of copying all the objects from a free-list backed space to a bump pointer space (or visa versa).
This occurs only on low RAM device prior to Android 8.0 when an app changes process states from a pause perceptible state (such as when the app is in the foreground, where the user can preceive a GC pause) to a non pause perceptible state (or visa versa).
HomogeneousSpaceCompact
Homogeneous space compaction is free-list space to free-list space compaction which usually occurs when an app is moved to a pause imperceptible process state. The main reasons for doing this are reducing RAM usage and defragmenting the heap.
DisableMovingGc
This is not a real GC reason, but a note that collection was blocked due to use of GetPrimitiveArrayCritical. while concurrent heap compaction is occurring. In general, the use of GetPrimitiveArrayCritical is strongly discouraged due to its restrictions on moving collectors.
HeapTrim
This is not a GC reason, but a note that collection was blocked until a heap trim finished.

GC Name
ART has various different GCs which can get run.
Concurrent mark sweep (CMS)
A whole heap collector which frees collects all spaces other than the image space.
Concurrent partial mark sweep
A mostly whole heap collector which collects all spaces other than the image and zygote spaces.
Concurrent sticky mark sweep
A generational collector which can only free objects allocated since the last GC. This garbage collection is run more often than a full or partial mark sweep since it is faster and has lower pauses.
Marksweep + semispace
A non concurrent, copying GC used for heap transitions as well as homogeneous space compaction (to defragement the heap).

Now We can discuss about Dalvik GC Log anlysis. 
This is how a typical Dalvik GC log line will look like:-

Below table summarizes each field in detail:

#	Field	Value	Description
1	Timestamp	07-01 15:56:19.815	Timestamp at which this Garbage Collection event ran
2	GC Reason	GC CONCURRENT	Reason why Garbage Collection event was triggered. Please refer below for different types of GC Reasons.
3	Objects freed	7078K	Amount of objects garbage collected. Totally 7078kb of objects are garbage collected (i.e. freed) in this event.
4	Heap usage	52464K/ 89052K	52464kb of objects are alive after this particular GC event. Total allocated heap size for this app is 89052 kb.
5	GC Pause Time	14ms+4ms	During certain phases of GC event, application is paused. In this GC event, pause time is 18 ms (i.e. 14 + 4 ms). During pause time, application freezes. One should target for low pause time.
6	GC Total Time	96ms	Amount of time this GC event took to complete. It includes the GC Pause time as well.

Dalvik GC Reason
What triggered the GC and what kind of collection it is. Reasons that might appear include:
GC_CONCURRENT
A concurrent GC that frees up memory as your heap begins to fill up.
GC_FOR_MALLOC
A GC was caused because your app attempted to allocate memory when your heap was already full, so the system had to stop your app and reclaim memory.
GC_HPROF_DUMP_HEAP
A GC that occurs when you request to create an HPROF file to analyze your heap.
GC_EXPLICIT
An explicit GC, such as when you call gc() (which you should avoid calling and instead trust the GC to run when needed).
GC_EXTERNAL_ALLOC
This happens only on API level 10 and lower (newer versions allocate everything in the Dalvik heap). A GC for externally allocated memory (such as the pixel data stored in native memory or NIO byte buffers)

As We all feel analyzing every single GC log line is very tedious work. So this is the obvious question "is there any tool for it ?" And the answer is Yes!!!!. We have few option:

• Use Android Studio inbuilt tool
• Use free online tools such as GCeasy.io

GCeasy.io – a universal Garbage collection log analyzer, to analyze Android GC logs. You can just upload the Android GC Logs to this tool. Tool parses GC log and generates report instantly. Report contains interactive graphs and insightful metrics.

So Hope this article address your Android GC log analysis understanding better. Please provide your feedback in  blog comment box.

Thanks

Saurabh

Happy Coding!!!!