GC日志查看和分析

Posted 2023-04-17

参考技术A 可以通过在java命令种加入参数来指定对应的gc类型，打印gc日志信息并输出至文件等策略。
GC的日志是以替换的方式(>)写入的，而不是追加(>>)，如果下次写入到同一个文件中的话，以前的GC内容会被清空。

启动命令:

结果:

也是一次minor gc,但是与前两次的gc原因不一样,这次的gc原因是：[Metadata GC Threshold],Metadata即元数据的意思,我们可以看出这是与虚拟机的元数据区有关系的一次gc;元数据区,在jdk1.8以前又叫永久代,从JDK8开始,永久代(PermGen)的概念被废弃掉了,取而代之的就是这里的称为Metaspace的存储空间;元空间和永久代是虚拟机对方法区这个概念的一个具体实现;对于元空间而言,这一块空间是存在本地内存当中的,因此,默认情况下,元空间的大小仅受本地内存限制,但我们可以通过参数来指定元空间的大小

这里元空间发生gc,说明元空间的内存不够了,到达了阀值;对元空间进行了一次垃圾回收,回收之前是245183K,回收之后是3769K

在元空间gc之后,紧接着发生了一次Full GC,且触发原因也是元空间不足

Android 性能优化 内存优化 分析GC日志

前言

Android虚拟机在发生垃圾回收 (GC) 事件时，会把相应消息会输出到 Logcat 中，可以看出来虚拟机的内存情况，这为我们做内存优化提供了另外一个可参考的依据，要尽量减少stop the world类型的GC。
本文介绍如何查看GC日志，先做到看懂GC日志。

Dalvik日志消息

在 Dalvik虚拟机中，主要是4.x系统的设备，每个 GC 都会将以下信息输出到 Logcat 中：

// 格式
D/dalvikvm(PID): GC_Reason Amount_freed, Heap_stats, External_memory_stats, Pause_time

1. GC_Reason：What triggered the GC and the kind of collection. Reasons that might appear include:

   • GC_CONCURRENT：
     A concurrent GC that frees up memory as your heap begins to fill up.
     堆开始分配内存时触发的并发GC；
   • GC_FOR_MALLOC(stop the world)：
     A GC 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.
     当堆内存已经满了再去分配内存时，虚拟机不得不去stop the world去回收内存了；
   • GC_HPROF_DUMP_HEAP
     A GC that occurs when you request to create an HPROF file to analyze your heap.
     dump内存时触发的GC；
   • GC_EXPLICIT
     An explicit GC, such as when you call System.gc() or Runtime.gc(). However, avoid calling this method; instead, trust the GC to run when needed.
     应用显示调用System.gc()时触发的GC；
   • GC_EXTERNAL_ALLOC
     A GC for externally allocated memory, such as the pixel data stored in native memory or NIO byte buffers. This happens only on API level 10 and lower. Newer versions allocate everything in the Dalvik heap.
     只在api <= 10且堆外内存GC时触发，如图片像素数据或NIO byte buffers。

2. Amount freed
   The amount of memory reclaimed from this GC.
   此次GC回收了多少内存；

3. Heap stats
   Percentage free of the heap and (number of live objects)/(total heap size).
   堆的可用空间百分比与（活动对象数量）/（堆总大小）。

4. External memory stats
   Externally allocated memory on API level 10 and lower: (amount of allocated memory)/(limit at which collection will occur).
   api <= 10的外部分配内存（已分配内存量）/（发生回收的限值）。

5. Pause time
   Larger heaps have larger pause times. 堆越大，暂停时间越长；
   Concurrent pause times show two pauses: one at the beginning of the collection and another near the end.
   并发暂停时间显示两个暂停：一个出现在回收开始时，另一个出现在回收快要完成时。

示例

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

这个GC日志的含义为：引起GC的原因是GC_CONCURRENT；本次GC释放的内存为2012K；堆的空闲内存百分比为63%，已用内存为3213K，堆的总内存为9291K；暂停的总时长为4ms。

ART日志消息

Unlike Dalvik, ART doesn’t log messages for GCs that were not explicitly requested. GC information is only printed when the GC is explicit or the GC pause exceeds 5ms or the GC duration exceeds 100ms. If the app is not in a pause-perceptible state, such as when the app is in the background, where the user cannot perceive a GC pause, then no GC information is printed except for explicit GCs.
Dalvik虚拟机会把所有GC日志都打印出来；但ART不会，ART只会打印显示GC、或耗时超过5msGC、或GC持续时间100ms等情况才会输出；另外当应用处于后台等用户不可感知状态时，也只会打印显示GC。

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)

1. GC Reason
   • Concurrent
     A concurrent GC that does not suspend app threads. This GC runs in a background thread and does not prevent allocations.
     不会挂起应用线程的并发 GC。此 GC 在后台线程中运行，而且不会阻止分配。
   • Alloc
     A GC initiated because the app attempted to allocate memory when the heap was already full. In this case, the garbage collection occurred in the allocating thread.
     由于应用在堆已满时尝试分配内存而引发的 GC。此时垃圾回收在分配线程中发生。
   • Explicit
     The garbage collection was explicitly requested by an app when you call System.gc() or Runtime.gc().
     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.
     不建议请求显式 GC，因为它们会阻止分配线程并不必要地浪费 CPU 周期，也可能造成其他线程cpu被抢占，则导致卡顿（应用出现卡顿、抖动或暂停）。
   • NativeAlloc
     A GC caused by native memory pressure from native allocations, such as bitmaps or RenderScript allocation objects.
     原生分配（例如位图或 RenderScript 分配对象）导致出现原生内存压力，进而引起的 GC。
   • CollectorTransition
     由堆转换引起的 GC。这由在运行时变更 GC 策略引起，例如应用在可察觉到暂停的状态之间切换时。回收器转换包括将所有对象从空闲列表空间复制到碰撞指针空间（反之亦然）。
     回收器转换仅在以下情况下出现：在搭载低于 Android 8.0 版本的低 RAM 设备上，应用将进程状态从可察觉到暂停的状态（例如应用在前台运行时，这种情况下，用户可以察觉 GC 暂停）更改为察觉不到暂停的状态（反之亦然）。
   • HomogeneousSpaceCompact
     同构空间压缩是空闲列表空间到空闲列表空间压缩，通常在应用进入到察觉不到暂停的进程状态时发生。这样做的主要原因是减少内存使用量并对堆进行碎片整理。
   • DisableMovingGc
     这不是 GC 原因，但请注意，由于在发生并发堆压缩时使用了 GetPrimitiveArrayCritical，因此回收遭到阻止。一般情况下，强烈建议不要使用 GetPrimitiveArrayCritical，因为它在移动回收器方面存在限制。
   • HeapTrim
     这不是 GC 原因，但请注意，在堆修剪完成之前，回收会一直受到阻止。
2. GC Name垃圾收集器名称：ART has various GCs that run:
   • Concurrent mark sweep (CMS)
     整个堆回收器，会回收除映像空间以外的所有其他空间。
   • Concurrent partial mark sweep
     几乎整个堆回收器，会回收除映像空间和 Zygote 空间以外的所有其他空间。
   • Concurrent sticky mark sweep
     分代回收器，只能释放自上次 GC 后分配的对象。此垃圾回收比完整或部分标记清除运行得更频繁，因为它更快速且暂停时间更短。
   • Marksweep + semispace
     非并发、复制 GC，用于堆转换以及同构空间压缩（对堆进行碎片整理）。
3. Objects freed
   The number of objects that were reclaimed from this GC from the non-large-object space.
   此次GC从非大型对象空间回收的对象数量。
4. Size freed
   The number of bytes that were reclaimed from this GC from the non-large-object space.
   此次GC从非大型对象空间回收的字节数量。
5. Large objects freed
   The number of objects in the large object space that were reclaimed from this garbage collection.
   此次GC从大型对象空间回收的对象数量。
6. Large object size freed
   The number of bytes in the large object space that were reclaimed from this garbage collection.
   此垃圾回收从大型对象空间回收的字节数量。
7. Heap stats
   Percentage free and (number of live objects)/(total heap size).
   可用空间百分比与（活动对象数量）/（堆总大小）。
8. Pause times
   In general, pause times are proportional to the number of object references that were modified while the GC was running. Currently, the ART CMS GC only has one pause, near the end of the GC. The moving GCs have a long pause, which lasts for the majority of the GC duration.
   通常情况下，暂停时间与 GC 运行时修改的对象引用数量成正比。当前，ART CMS GC 仅在 GC 即将完成时暂停一次。移动 GC 的暂停时间较长，会在 GC 的大部分时间持续。

示例

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日志的含义为：引起GC原因是Explicit ；垃圾收集器为CMS收集器；释放AllocSpace对象的数量为104710个，释放字节数为7MB；释放LOS大对象的数量为21个，释放大对象字节数为416KB；堆的空闲内存百分比为33%，已用内存为25MB，堆的总内存为38MB；GC暂停时长为1.230ms，GC总时长为67.216ms。

参考：
官方文档
看懂Android GC日志（译）
Android内存优化（二）DVM和ART的GC日志分析