StackTips

Understanding the Garbage Collection Logs in Android Applications

Memory utilisation on the mobile app has a significant impact on the customer experience. If your app creates a lot of objects, then Android Run Time (ART) environment will trigger Garbage Collection (GC) frequently. Android Garbage Collection is an automatic process which removes unused objects from memory. However, frequent Garbage Collection consumes a lot of CPU + it will also pause the app. Frequent pauses can jank the app (i.e. stuttering, juddering, or halting).

Thus, you need to understand how many objects your app is creating, how frequently Garbage collection is triggered, how much time it takes to complete, how much memory is reclaimed after every event. All this information is present in the runtime log messages. Whenever a GC event runs, a log line is printed in the runtime log messages. You can view those log lines through logcat.

This is how a typical ART GC log line will look:

07-01 16:00:44.690: I/art(801): Explicit concurrent mark sweep GC freed 65595(3MB) 
AllocSpace objects, 9(4MB) LOS objects, 34% free, 38MB/58MB, paused 1.195ms total 87.219ms

This one single log line has multiple fields. Let’s review them:

ART-3

#FieldValueDescription
1Timestamp07-01 16:00:44.690Timestamp at which this Garbage Collection event ran
2GC ReasonExplicitReason why Garbage Collection event was triggered. ‘Explicit’ indicates that garbage collection was explicitly requested by an app, for example, by calling gc() or gc().
3GC Nameconcurrent mark sweepART 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.
4Objects freed65595(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.
5Large objects freed9(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)
6Heap usage38MB/58MB38mb of objects is alive after this particular GC event. Total allocated heap size for this application is 58mb.
7GC Pause Time1.195msDuring 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.
8GC Total Time87.219msAmount of time this GC event took to complete. It includes the GC Pause time as well.

Tools

<img class="wp-image-2240 size-full" src="https://bloggceasy.files.wordpress.com/2017/05/art-1.png?w=736" alt="ART-1" width="736" height="367" /> Fig 1: Android memory usage – report generated by GCeasy.io<strong><em> </em></strong> <img class="wp-image-2241 size-full" src="https://bloggceasy.files.wordpress.com/2017/05/art-2.png?w=736" alt="ART-2" width="736" height="383" /> Fig 2: Android GC Statistics – report generated by GCeasy.io

As it might get tedious to analyse every single GC log line, you can also consider using free online tools such as GCeasy.io – a universal Garbage collection log analyser, to analyses Android GC logs. You can just upload the Android GC Logs to this tool. Tool parses GC log and generates report instantly. The report contains interactive graphs and insightful metrics. A Few excerpts from this report were given above for your reference.

sreepathy_ramanujam avtar

Ram Lakshmanan

Every single day millions & millions of people in North America - bank, travel and do commerce using the applications that Ram Lakshmanan has architected. Ram is an acclaimed speaker in major conferences on the scalability, availability, performance topics. Recently he has founded a startup, which specializes in troubleshooting performance problems.