Android memory output messages
09-16 14:11:43.713 9659-9661/? D/dalvikvm: GC_CONCURRENT freed 566K, 13% free 5236K/5984K, paused 3ms+2ms, total 26ms
GC_CONCURRENT
GC_CONCURRENT表示触发垃圾收集的原因，有以下几种：
- GC_MALLOC, 内存分配失败时触发
- GC_CONCURRENT，堆已满, 当分配的对象大小超过384K时触发
- GC_EXPLICIT，对垃圾收集的显式调用(System.gc)
- GC_EXTERNAL_ALLOC，外部内存分配失败时触发
freed 566K
freed 566K 表示本次垃圾收集释放了 566K 的内存，
13% free 5236K/5984K
13% free 5236K/5984K，其中 5984K 表示当前内存总量，5236K 表示可用内存，13%表示可用内存占总内存的比例。
5984 千字节=5.84375 兆字节
paused 3ms+2ms
paused 3ms+2ms，收集垃圾的时间, 第一个时间值表示markrootset的时间，第二个时间值表示第二次mark的时间。如果触发原因不是GC_CONCURRENT，这一行为单个时间值，表示垃圾收集的耗时时间。
参考文章
Android: Understanding DDMS Logcat memory output messages
posted 12 May 2012, 06:10 by Bernd van Velsen [ updated 12 May 2012, 06:13 ]
If you have been testing your android applications using a hardware device and the LogCat view in Eclipse, then the next lines will be nothing new. However, what do these lines mean? And what do they tell you? GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms GC_CONCURRENT freed 379K, 42% free 3856K/6535K, external 0K/0K, paused 2ms+3ms GC_EXPLICIT freed 144K, 41% free 3898K/6535K, external 0K/0K, paused 32ms GC_CONCURRENT freed 334K, 40% free 4091K/6727K, external 0K/0K, paused 2ms+3ms These lines are part of the Garbage Collection(GC) process of Android. Each time a GC is triggered; this is displayed in the LogCat view in this way. It can tell you lots of things, and also give you a heads up that you might run into memory problems sooner or later. Therefor we will go into more detail about each part of these lines so we can better understand them
Reason
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
The first part tells you the reason of the GC. And why the GC occured. There are 5 types of GC in Android
- 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_EXPLICIT: Triggered when an application calls System.gc(). This should actually never be called since the virtual machine is quite capable of handling GC.
- GC_EXTERNAL_MALLOC: Used for externally allocated memory like bitmaps and NIO direct bytebuffers. This is only on pre-Honeycomb devices because from Honeycomb the external memory is allocated inside dalvik heap
- GC_FOR_MALLOC: Triggered when the heap is full and the application needs more memory. This will stop your application to perform a GC
- GC_HPROF_DUMP_HEAP: Triggered when an HPROF file is created for memory analysis
Result
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
This part tells you how much memory was freed by this GC sweep
Heap Statistics
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
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 41% free, there is 3673k memory in use and the total heap size is 6151k.
External Memory Statistics
GC_EXTERNAL_ALLOC freed 1125K, 47% free 6310K/11847K, external 1051K/1103K, paused 46ms GC_EXTERNAL_ALLOC freed 295K, 47% free 6335K/11847K, external 1613K/1651K, paused 41ms
This part tells you some information about the externally allocated memory. This is where in pre-Honeycomb the bitmaps were stored. So in the first example above you can see that there is 1051k in use and there is a limit of 1103k.
The two lines above were triggered about 100ms apart. So you can clearly see in the first line that the external memory was almost full. So a GC_EXTERNAL_ALLOC was triggered and the external memory was enlarged to 1651k
GC Pause Time
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
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. These times are generally short for a concurrent collection and relatively big for all other collections as you can see in the example.
The reason why the GC_CONCURRENT is smaller is because this GC is done on a separate thread that won't interfere with your application. These times are generally smaller then 5ms.
If you would like to know more about this topic view Google I/O 2011: Memory management for Android Apps on Youtube. All information in this post is collected from that video
译文：理解Android中垃圾回收日志信息
如果你是一名Android开发者并且常常看程序日志的话，那么下面的这些信息对你来说可能一点都不陌生。
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms GC_CONCURRENT freed 379K, 42% free 3856K/6535K, external 0K/0K, paused 2ms+3ms GC_EXPLICIT freed 144K, 41% free 3898K/6535K, external 0K/0K, paused 32ms GC_CONCURRENT freed 334K, 40% free 4091K/6727K, external 0K/0K, paused 2ms+3ms
但是这些到底是什么，又有什么含义呢？
上面的这几行就是Android系统垃圾回收的部分输出信息。每当垃圾回收被触发的时候，你就可以通过logcat查看到这样的信息。这样短短的一行的日志有着很大的信息量。比如通过日志我们可以发现程序可能有内存（泄露）问题。本文将具体介绍这些日志信息的每一部分的含义来帮助帮助大家更好地了解垃圾回收的运行情况。
原因
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
红颜色标出的部分就是垃圾回收触发的原因。在Android中有五种类型的垃圾回收触发原因。
- GC_CONCURRENT 当堆内存增长到一定程度时会触发。此时触发可以对堆中的没有用的对象及时进行回收，腾出空间供新的对象申请，避免进行不必要的增大堆内存的操作。
- GC_EXPLICIT 当程序中调用System.gc()方法触发。这个方法应避免出现在程序中调用。因为JVM有足够的能力来控制垃圾回收。
- GC_EXTERNAL_MALLOC 当Bitmap和NIO Direct ByteBuffer对象分配外部存储（机器内存，非Dalvik堆内存）触发。这个日志只有在2.3之前存在，从2.3系统开始，垃圾回收进行了调整，前面的对象都会存储到Dalivik堆内存中。所以在2.3系统之后，你就再也不会看到这种信息了。
- GC_FOR_MALLOC 当堆内存已满，系统需要更多内存的时候触发。这条日志出现后意味着JVM要暂停你的程序进行垃圾回收操作。
- GC_HPROF_DUMP_HEAP 当创建一个内存分析文件HPROF时触发。
结果
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
这部分数据告诉我们JVM进行垃圾回收释放了多少空间。
堆内存数据
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
这部分告诉我们堆内存中可用内存占的比例，当前活跃的对象总的空间，以及当前堆的总大小。所以这里的数据就是41%的堆内存可用，已经使用了3673K，总的堆内存大小为6151K。
外部存储数据
GC_EXTERNAL_ALLOC freed 1125K, 47% free 6310K/11847K, external 1051K/1103K, paused 46ms GC_EXTERNAL_ALLOC freed 295K, 47% free 6335K/11847K, external 1613K/1651K, paused 41ms
这部分数据告诉我们外部存储（位于机器内存）对象的数据。在2.3之前，bitmap对象存放在机器内存。因此在第一条数据中我们可以看到以有1051K使用，外部存储为1103K。
上面两行数据相差100毫秒，我们可以看到第一条数据表明外部存储快满了，由于GC_EXTERNAL_ALLOC被触发，外部存储空间扩大到了1651K。
垃圾回收暂停时间
GC_CONCURRENT freed 178K, 41% free 3673K/6151K, external 0K/0K, paused 2ms+2ms GC_EXPLICIT freed 6K, 41% free 3667K/6151K, external 0K/0K, paused 29ms
这部分数据表明垃圾回收消耗的时间。在GC_CONCURRENT回收时，你会发现两个暂停时间。一个是在回收开始的暂停时间，另一个时在回收结束的暂停时间。GC_CONCURRENT从2.3开始引入，相比之前的程序全部暂停的垃圾回收机制，它的暂停时间要小的多。一般少于5毫秒。因为GC_CONCURRENT的绝大多数操作在一个单独的线程中进行。
本文中内容摘自 Google I/O 2011: Memory management for Android Apps，如果感兴趣，请访问这里了解更多。
