Understanding Android GC Messages

Question

I have the following message on my catlog,

GC_CONCURRENT freed 456K, 19% free 2753K/3360K, paused 5ms+9ms, total 378ms

I am trying to make sense of the last value total. I've checked other GC related question on the site they either have two pauses associated with the concurrent GC or a single total pause for the non concurrent GC. Why do i have two? Did my app paused for 5+9 ms or 378 ms? What exactly is total?

Answer 1

Don't have a definitive answer, but from what I get, GC_CONCURRENT is a garbage collection that runs in a separate thread. This means that while it might take a total of X ms (378 in your case) to run, your actual running thread will not be blocked for that long. It will only be blocked a bit at the beginning and at the end of the concurrent garbage collection process (5+9=14ms in your example)

This type of garbage collection is auto-triggered by the JVM when it decides it's a good time to do that (usually when the heap has grown dangerously high). Other types of GC, like GC_EXPLICIT (if I'm not mistaking on the name) is triggered when you do a

System.gc();

in your code. For this type of garbage collection it will only report one time (like Y ms) and in this case your thread will actually be blocked for that amount of time until this type of GC process finishes.

Answer 2

GC_CONCURRENT: Triggered when the heap is growing. So it can reclaim memory in time so the heap doesn't need to be enlarged

GC_CONCURRENT freed 456K

This part tells you how much memory was freed by this GC sweep

GC_CONCURRENT freed 456K, 19% free 2753K/3360K

This part tells how much % of the heap is free, the size of the alive objects and the total size of the heap. So in the above example the 19% free, there is 2753Kmemory in use and the total heap size is 3360K.

The last part of the log tells you how long the GC took. on a GC_CONCURRENT collection you will see 2 times. one at the beginning of the collection, and one at the end.

For non-concurrent GC events, there is only one pause time and it's typically much bigger. E.g. paused 378ms

Source:

https://sites.google.com/site/pyximanew/blog/androidunderstandingddmslogcatmemoryoutputmessages

Another place where things are explained clearly...

http://www.youtube.com/watch?v=_CruQY55HOk