长河落日圆: GC

MinorGC

13165.625①: [GC (GCLocker Initiated GC)② 13165.625: [ParNew③: 77440K->6531K(77440K)④, 0.0064810 secs] 231539K->160787K(334612K)⑤, 0.0065377 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]⑥

上面是一次普通的小型垃圾回收(MinorGC)的日志；

① 时间标记，GC开始的时间（距离进程启动），单位秒；

② GC的发生原因，最常见的是Allocation Failure 和 GC Locker；

GC Cause	Description
Allocation Failure	Application tried to make a new allocation and failed due to lack of available space in Young generation; hence Minor GC is required. On Linux, the JVM can trigger a GC if the kernel notifies there isn't much memory left via mem_notify. 程序试图在新生区创建对象时，出现空间不足从而导致创建失败；因此需要触发一个MinorGC；
GC Locker	GC is started after all threads leave the JNI Critical region. For more information on JNI, refer to the Java Native Interface documentation website. GC is blocked when any thread is in the JNI Critical region and can start only when all of them outside of it. JNI的critical region会阻止GC的发生，这个机制会允许执行的线程执行完毕，由最终的release方法退出JNI的critical region；当有线程进入critical region时，此时发生了gc需求，系统会阻止其他线程进入并等待所有进入的线程退出，直到所有线程退出，会触发一次gc；
G1 Evacuation Pause	This is actual only for the G1 collector. It indicates that it is copying live objects from one set of regions (Young and sometimes Young + Tenured, which is called Mixed) to another set of regions.
G1 Humongous Allocation	This is actual only for the G1 collector. Humongous is an allocation when its size is greater than 50% of one region size; the object then allocated in special space. Nevertheless, it also causes normal GC collection to get more (possibly continuous also) space for such objects.
CMS Initial Mark	Initial mark phase of CMS, for more details, see Phases of CMS. It also triggers Young Space collection.
System.gc()	There was a `System.gc()` call in the application code. You can start JVM with the `-XX:+DisableExplicitGC` flag to disable such behavior.
Adaptive Size Ergonomics	Indicates you are using the adaptive heap size policy (ability to change Young and Tenured spaces size at runtime), enabled via the `-XX:+UseAdaptiveSizePolicy` flag. By default, it is enabled in the recent versions of JVM.
Allocation Profiler	This is actual only for versions of Java before 8 and only when `-Xaprof` is set. It triggers just before JVM exits.
Heap Inspection	GC was triggered by an inspection operation on the heap, most probably by the jmap tool with the `-histo:live` flag set.
Heap Dump	GC was initiated before heap dump is made by some profiling instrument.
No GC	Normally, you shouldn't see this reason. It was occurring in older Java versions, in case jstat command was started before any collection occurred. Other case is when jstat checks GC without any GC activity.
Last Ditch Collection	When Metaspace (Java 8+) or PermGen (Java 7-) is full and you can't allocate a new object here, JVM first tries to clean it, triggering appropriate collector. If that's not possible, it then tries to expand it. If that doesn't work as well, it triggers Full GC with this cause name. Soft references are being cleaned during it as well.
Perm Generation Full	Triggered as a result of an allocation failure in PermGen. Actual for Java versions prior to 8.
Metadata GC Threshold	Triggered as a result of an allocation failure in Metaspace. Metaspace is a replacement for PermGen in Java 8+.
JvmtiEnv ForceGarbageCollection	Something called the JVM tool interface function ForceGarbageCollection.

③ ParNew是JVM中的一种垃圾回收器；它是Serial收集器的多线程版本；

④ 新生区回收前->回收后(总可用)的大小；

⑤ heap回收前->回收后(总可用)

⑥ 时间消耗情况，具体参考下方Times说明

CMS fullGC日志

启用了CMS的一次fullGC日志；

505: [GC (CMS Initial Mark) [1 CMS-initial-mark: 241153K(257172K)] 251001K(334612K), 0.0165025 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]

522: [CMS-concurrent-mark-start]

764: [CMS-concurrent-mark: 1.243/1.243 secs] [Times: user=1.55 sys=0.80, real=1.25 secs]

765: [CMS-concurrent-preclean-start]

775: [CMS-concurrent-preclean: 0.010/0.011 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]

775: [CMS-concurrent-abortable-preclean-start]

 CMS: abort preclean due to time 13163.867: [CMS-concurrent-abortable-preclean: 4.677/5.092 secs] [Times: user=5.95 sys=1.03, real=5.09 secs]

868: [GC (CMS Final Remark) [YG occupancy: 66334 K (77440 K)]13163.868: [Rescan (parallel) , 0.0552409 secs]13163.923: [weak refs processing, 0.0012519 secs]13163.924: [class unloading, 0.0099594 secs]13163.934: [scrub symbol table, 0.0051363 secs]13163.939: [scrub string ta

ble, 0.0014047 secs][1 CMS-remark: 241153K(257172K)] 307488K(334612K), 0.0740422 secs] [Times: user=0.14 sys=0.00, real=0.07 secs]

945: [CMS-concurrent-sweep-start]

065: [CMS-concurrent-sweep: 0.120/0.120 secs] [Times: user=0.12 sys=0.00, real=0.12 secs]

065: [CMS-concurrent-reset-start]

074: [CMS-concurrent-reset: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

关于CMS垃圾回收阶段说明

CMS Initial Mark：初始标记阶段，这个阶段标记由根可以直接到达的对象，该阶段会停止JVM的所有线程(STOP-THE-WORLD)；
CMS concurrent-mark：并发标记阶段，在第一个阶段被暂停的线程重新开始运行，由前阶段标记过的对象出发，所有可到达的对象都在本阶段中标记。本阶段不会影响对外服务；
CMS-concurrent-preclean：预清理阶段，在本阶段，会查找前一阶段执行过程中,从新生代晋升或新分配或被更新的对象。通过并发地重新扫描这些对象，预清理阶段可以减少下一个stop-the-world 重新标记阶段的工作量。
CMS Final Remark(Rescan)：该阶段会停止JVM所有响应(STOP-THE-WORLD)，从根及被其引用对象开始，重新扫描 CMS 堆中残留的更新过的对象；
CMS-concurrent-sweep：开始并发清理阶段，在清理阶段，应用线程还在运行。
CMS-concurrent-reset：开始并发重置，重新初始化CMS内部数据结构，以备下一轮 GC 使用；

关于Times说明

[Times: user=1.55 sys=0.80, real=1.25 secs]

user：指的是cpu在用户模式下耗费的时间（不包含kernel），谨代表在当前进程中耗费的时间；
sys：指的是kernel耗费的cpu时间，同上，也仅代表当前进程由于调用kernel所耗费的cpu时间；
real：表示一次调用实际耗费时间，通俗说指的是墙上的时钟走过的时间。
user+sys：表示本次调用总共耗费的CPU时间，如果是多核心并发处理，实际耗费时间要小于这两个的和；

总结

根据上面的CMS日志，可以看到，一次fullGC导致的程序暂停响应的时间是0.01+0.07=0.08s

GC

GC-垃圾回收是一种动态存储管理技术，它可以自动释放那些不再被使用的对象，按照特定的算法来实现资源自动回收。

垃圾收集方式

引用计数

堆中的每个对象对应一个引用计数器，每当创建或重新赋值的时候，引用计数器就+1，而当对象出了作用域之后，计数器-1，直到计数器为0，就达到了被回收的条件。

引用计数方式速度较快，不会产生停顿。但是开销较大，因为每个对象都对应了一个计数器。

对象引用遍历

从根集开始扫描，识别出哪些对象可达，哪些不可到达。并利用某种方式标记可达对象。

垃圾收集算法

复制

找到活动对象并拷贝到新的空间。这种算法适合存活对象较少的情况，内存开销较大。

标记清除

从根开始扫描，将活动对象标记。然后再扫描未标记的对象，一次清除。此方法的优点是不需要移动对象，仅对不存活对象操作，适合存活对象较多的情况，容易产生内存碎片。

标记压缩

标记清除的基础上，移动活动对象。缺点是成本较高，优点是没有内存碎片。

分代回收

GC是对JVM堆中的对象进行回收，在上一篇博客中，hotspot堆分为young，old和perm三部分。新生对象首先进入young区，随着young区不断的增加，一些老的对象将被移到old区。而perm区主要存储了java class的类型信息和静态变量等。

youngGC

即年轻代垃圾回收，当创建新对象，Eden空间不足时，触发youngGC。有三种选择

1. 串行GC

将Eden中存活的对象移到From->To->Old.适用于单线程，单cpu，新生代较小，要求不高的应用。在client模式或32位机器下默认选择。

启用：-XX:+UseSerialGC

2. 并行回收GC，Parallel Scavenge

多线程执行，适应多CPU，要求较高的应用。在server模式下是默认的。启用：-XX:+UseParallelGC, 在8核心以下的机器上默认为cpu核心数，大于8核，则默认为3+(核心数*5)/8.也可以通过-XX:ParallelGCThreads=8指定。

3. ParNew GC

需配合旧生代使用CMSGC。启用：-XX:+UseParNewGC.可以通过-XX:DisableExplicitGC禁用。

OldGC

1. 旧生代串行GC

算法：标记清除和标记压缩。采用单线程执行，耗时较长，需要暂停应用。client模式或32位机默认采用这种模式。-XX:+PrintGCApplicationStoppedTime可以查看应用暂停时间。

2. 旧生代并行GC

算法：标记压缩算法。采用多线程方式，暂停时间减少。server模式默认采用这种回收方式。

3. 旧生代并发GC

采用标记清除算法。对GC进行并发执行，大大缩短应用暂停时间，但是整体GC时间会加长。启用方式：-XX:+UseConcMarkSweepGC。可以通过-XX:ParallelCMSThreads=10指定并发线程数。通过-XX:+CMSClassUnloadingEnabled来启用持久代CMS.

垃圾整理：使用-XX:UseCMSCompactAtFullCollection每次fullGC后都会启动垃圾整理.-XX:CMSFullGCsBeforeCompaction=2表示2次fullGC后开始整理。

fullGC

旧生代和持久代GC时，即是对新生代，旧生代持久代都GC，FullGC。

执行时，先对新生代GC，可以通过-XX:ScanengeBeforeFullGC禁止fullGC时对新生代GC，然后对旧生代持久代进行GC。

触发时机：

1. system.gc，可以通过-XX:DisableExplicitGC禁用。

2. 旧生代空间不足

3. 持久代空间满

4. CMSGC时出现promotion failed

5. 统计youngGC后要移到旧生代的对象大于旧生代剩余空间

查看JVM使用的GC算法

找到java进程ID，使用jmap命令：

jmap -heap {pid}

会打印出JVM的基本信息，包括分区信息，回收算法等。
打印之前先看一下启动参数：

java -server -Xms512m -Xmx512m -XX:NewSize=100m -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=58 -XX:PermSize=64m -XX:MaxPermSize=64m -XX:ThreadStackSize=512

下面是jvm-heap信息：

Attaching to process ID 31410, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 20.8-b03

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 536870912 (512.0MB)
   NewSize          = 104857600 (100.0MB)
   MaxNewSize       = 283508736 (270.375MB)
   OldSize          = 314572800 (300.0MB)
   NewRatio         = 7
   SurvivorRatio    = 8
   PermSize         = 67108864 (64.0MB)
   MaxPermSize      = 67108864 (64.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 94371840 (90.0MB)
   used     = 7155464 (6.823982238769531MB)
   free     = 87216376 (83.17601776123047MB)
   7.582202487521702% used
Eden Space:
   capacity = 83886080 (80.0MB)
   used     = 6906936 (6.586967468261719MB)
   free     = 76979144 (73.41303253173828MB)
   8.233709335327148% used
From Space:
   capacity = 10485760 (10.0MB)
   used     = 248528 (0.2370147705078125MB)
   free     = 10237232 (9.762985229492188MB)
   2.370147705078125% used
To Space:
   capacity = 10485760 (10.0MB)
   used     = 0 (0.0MB)
   free     = 10485760 (10.0MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 432013312 (412.0MB)
   used     = 7523480 (7.174949645996094MB)
   free     = 424489832 (404.8250503540039MB)
   1.7414926325233238% used
Perm Generation:
   capacity = 67108864 (64.0MB)
   used     = 39960504 (38.10930633544922MB)
   free     = 27148360 (25.89069366455078MB)
   59.545791149139404% used

长河落日圆

2017年3月2日星期四

GC日志分析