Open wittyResry opened 6 years ago
[GC [1 CMS-initial-mark: 463236K(515960K)] 464178K(522488K), 0.0018216 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] //STW
463236K above is the space occupied by objects in the old (CMS) generation at the start of the collection. Not all those objects are necessarily alive.
515960K is the total size of the old (CMS) generation. This value changes if the generation grows or shrinks.
464178K is the sum of the space occupied by objects in the young generation and the old (CMS) generation.
522488K is the total size of the heap (young generation plus old (CMS) generation)
0.0018216 secs is the duration of the initial mark pause. The initial mark is a stop-the-world phase.
After the initial mark completes the CMS concurrent mark starts. The concurrent mark phase is a concurrent phase and can be interrupted by young generation collections. In this case the ParNew (UseParNewGC) is being used to collect the young generation. When a ParNew collection is ready to start, it raises a flag and the CMS collector yields execution to ParNew and waits for ParNew to finish before resuming.
[GC[ParNew: 6528K->702K(6528K), 0.0130227 secs] 469764K->465500K(522488K), 0.0130578 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
6528K is the space in the young generation occupied by objects at the start of the ParNew collection. Not all those objects are necessarily alive.
702K is the space occupied by live objects at the end of the ParNew collection.
6528K is the total space in the young generation.
0.0130227 is the pause duration for the ParNew collection.
469764K is the space occupied by objects in the young generation and the old (CMS) generation before the collection starts.
465500K is the space occupied by live objects in the young generation and all objects in the old (CMS) generation. For a ParNew collection, only the liveness of the objects in the young generation is known so the objects in the old (CMS) generation may be live or dead.
522488K is the total space in the heap.
[Times: user=0.05 sys=0.00, real=0.01 secs] is like the output of time(1) command. The ratio user / real give you an approximation for the speed up you're getting from the parallel execution of the ParNew collection. The sys time can be an indicator of system activity that is slowing down the collection. For example if paging is occurring, sys will be high.
[GC[ParNew: 6526K->702K(6528K), 0.0136447 secs] 471324K->467077K(522488K), 0.0136804 secs] [Times: user=0.04 sys=0.01, real=0.01 secs]
[GC[ParNew: 6526K->702K(6528K), 0.0161873 secs] 472901K->468830K(522488K), 0.0162411 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
[GC[ParNew: 6526K->702K(6528K), 0.0152107 secs] 474654K->470569K(522488K), 0.0152543 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
...
[GC[ParNew: 6526K->702K(6528K), 0.0144212 secs] 481073K->476809K(522488K), 0.0144719 secs] [Times: user=0.05 sys=0.00, real=0.01 secs]
This is the completion of the concurrent marking phase. After this point the precleaning starts.
[CMS-concurrent-mark: 1.039/1.154 secs] [Times: user=2.32 sys=0.02, real=1.15 secs]
The 1.039 is the elapsed time for the concurrent marking. The 1.154 is the wall clock time.
The "Times" output is less meaningful because it is measured from the start of the concurrent marking and includes more than just the work done for the concurrent marking.
This is the end of the precleaning phase.
[CMS-concurrent-preclean: 0.006/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
The format of the precleaning phase output is analogous to that of the concurrent marking phase.
[GC[ParNew: 6526K->702K(6528K), 0.0141896 secs] 482633K->478368K(522488K), 0.0142292 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
[GC[ParNew: 6526K->702K(6528K), 0.0162142 secs] 484192K->480082K(522488K), 0.0162509 secs] [Times: user=0.05 sys=0.00, real=0.02 secs]
The remark phase is scheduled so that it does not occur back-to-back with a ParNew so as not to appear to be a pause that is the sum of the ParNew and the remark pause. A second precleaning phase is started and is aborted when the remark phase is ready to start. Aborting this second precleaning phase is the expected behavior. That it was aborted is not an indication of an error. Since the remark phase is waiting, why not preclean but don't delay the remark for the sake of precleaning.
[CMS-concurrent-abortable-preclean: 0.022/0.175 secs] [Times: user=0.36 sys=0.00, real=0.17 secs]
This is the remark phase.
[GC[YG occupancy: 820 K (6528 K)][Rescan (parallel) , 0.0024157 secs][weak refs processing, 0.0000143 secs][scrub string table, 0.0000258 secs] [1 CMS-remark: 479379K(515960K)] 480200K(522488K), 0.0025249 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]//*STW
[YG occupancy: 820 K (6528 K)] shows that at the start of the remark the occupancy (sum of the total of the allocated objects in the young generation is 820K out of a total of 6528K. The length of the remark pause depends to some degree on the occupancy of the young generation so we print it out.
The "Rescan" completes the marking of live objects while the application is stopped. In this case the rescan was done in parallel and took 0.0024157 secs.
"weak refs processing" and "scrub string table" are tasks done during the remark. Those tasks took 0.0000143 secs and 0.0000258 secs, respectively. If those numbers dominate the remark pause time, they can explain unexpectedly large pauses. Not that they cannot legitimately be large. Just that generally they are not and when they are, take note. If the weak refs processing is dominate, you might be able to cut that time down by using parallel reference processing (-XX:+ParallelRefProcEnabled). No comment on the case when scrub string table is dominant. I've never had to deal with it.
The concurrent sweeping phase starts at the end of the remark.
[GC[ParNew: 6526K->702K(6528K), 0.0133250 secs] 441217K->437145K(522488K), 0.0133739 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
[GC[ParNew: 6526K->702K(6528K), 0.0125530 secs] 407061K->402841K(522488K), 0.0125880 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
...
[GC[ParNew: 6526K->702K(6528K), 0.0121435 secs] 330503K->326239K(522488K), 0.0121996 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
The sweep phase ends here.
[CMS-concurrent-sweep: 0.756/0.833 secs] [Times: user=1.68 sys=0.01, real=0.83 secs]
The format above is analogous to that of the concurrent marking.
And lastly the reset phase.
[CMS-concurrent-reset: 0.009/0.009 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
It is not expected that another concurrent CMS collection start before several ParNew collections have been done. If another CMS collection starts immediately, check how full the old (CMS) generation is. If the old (CMS) generation is close to being full immediately after the end of a collection, the heap might be too small.
I took this log with an early build of JDK8
java version "1.8.0-ea" Java(TM) SE Runtime Environment (build 1.8.0-ea-b73) Java HotSpot(TM) Server VM (build 25.0-b14, mixed mode)
and used the flags
-server -XX:+UseConcMarkSweepGC -XX:NewRatio=8 -XX:-PrintGCCause -XX:ParallelGCThreads=4 -Xmx1g -XX:+PrintGCDetails
I usually also use -XX+PrintTimeStampsps to get time stamps in the logs and use -XX:+PrintGCDateStamps if I want to correlate the GC output to application events.
-XX:+UseG1GC -XX:+UnlockExperimentalVMOptions -XX:G1NewSizePercent=26 -XX:MaxGCPauseMillis=150 -XX:+DisableExplicitGC -XX:InitiatingHeapOccupancyPercent=30 -XX:G1HeapRegionSize=32m -XX:G1HeapWastePercent=5 -XX:G1MixedGCLiveThresholdPercent=75 -XX:G1ReservePercent=15 -XX:MaxTenuringThreshold=6 -XX:+ParallelRefProcEnabled -XX:CICompilerCount=6 -XX:StringTableSize=2000039 -XX:+UseStringCache -XX:InitialCodeCacheSize=1024m -XX:ReservedCodeCacheSize=1024m -XX:SoftRefLRUPolicyMSPerMB=0 -verbose:gc -XX:+PrintGCDetails -XX:+PrintJNIGCStalls -XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/admin/logs -Xloggc:/home/admin/logs/gc.log -XX:ErrorFile=/home/admin/logs/hs_err_pid%p.log
参数 | 说明 |
---|---|
-XX:+UseG1GC | jvm使用G1作为垃圾收集器 |
-XX:MaxGCPauseMillis=150 | 声明G1最大停顿目标,这个参数将影响最终G1每次回收的内存区域的范围,G1预估停顿时间来尽量的满足这个目标值 |
-XX:InitiatingHeapOccupancyPercent=30 | 设置启动GC标记的时机,指老年代使用的空间占整个堆内存的比例。默认值是45%(这个默认值会和一组新生代的默认值会形成一个可能的冲突配置,导致Full GC发生) |
-XX:G1NewSizePercent=26 | 需要开启UnlockExperimentalVMOptions的情况下,设置新生代范围大下限,G1新生代的堆大小默认会自动在5%-80%之间根据G1统计信息自动决策,而这个决策也会带来上面提到可能的Full GC。如果使用G1的默认配置,当新生代的大小超过 55%时,在这个期间老年代的内存阀值不可能使用超过堆的45%,从而达不到触发默认标记的阀值,老年代区域会一直得不到回收,当内存不够时,就会降级为SerialOld做Full GC,这个对于大堆内存相当可怕,会长达几秒到数十秒的时间。 |
-XX:MaxTenuringThreshold | 最大存活代数阀值,对于我们的应用场景来看,一般存活在4-6代后,对象的死亡速度会快速下降,6代以后对象每次young gc过后只会有很少的对象被回收,所以一般设置在6代即可以满足我们的应用需求,让这部分对象晋升到老年代,防止新生代过多的被反复复制。 |
-XX:G1ReservePercent | 设置预留堆的大小作为“假顶”,降低晋升失败的可能。默认值为 10。 |
-XX:G1HeapRegionSize=32M | 设置各子堆区的大小。根据工效学通过堆大小确定该参数的默认值,但实践发现这个工效学算法在jdk 1.7中的G1中还不太靠谱,最小值为 1 MB,最大值为 32 MB. |
-XX:+UnlockExperimentalVMOptions | 部分更加细节的控制参数,需要开启该参数 |
-XX:G1HeapWastePercent=5 | initial-mark阶段后,GC会对可回收资源与G1HeapWastePercent进行比较,如果大于这个阀值,将在下一次young gc时进行mixed gc,对老年代进行内存加收,这个参数是一个很重要的参数项 |
-XX:G1MixedGCLiveThresholdPercent=75 | 用于计算Region是否适合被回收的一个阀值,这里涉及到成本与收益的问题,如果这个值太高,会导致回收成本上升,因为存活对象占比太高,会导致大量活对象被copy,但回收的资源有限,而这个阀值太低导致可回收资源变少。所以需要根据应用的内存情况进行一些微调来达最佳效果,默认值75,只有在这个值之下,才会被入先到CSet集合。 |
-XX:+ParallelRefProcEnabled | 开启并行引用标记,开启后可以提引用标记的速度 |
-XX:SoftRefLRUPolicyMSPerMB | 软引用回收规则,这里设置多长时间不被访问时,在GC时被回收。发现spring中大量的使用了SoftRef来处理类信息缓存,而如果不化零为整,在每次GC时回收掉这些软引用,会导致偶发性的因SoftRef数量大导致的Remark时间增大的情况。 |
-XX:+PrintGCDetails | 打印GC的回收日志详情,分析GC使用 |
标准参数:
-client
-classpath classpath
-verbose
非标准参数(不被所有虚拟机实现),以 -X 开头:
-Xms1800m
-Xloggc:file
不稳定参数(随时有可能在升级中取消),以-XX开头:
-XX:MaxPermSize=340m
-XX:+UseConcMarkSweepGC
命令获取当前JVM所有可设置的参数以及当前默认值:
java -XX:+PrintFlagsInitial 可输出所有可设置参数及当前默认值
java -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+PrintFlagsFinal -version
➜ my-spring-boot-test git:(master) ✗ jar tvf target/my-spring-boot-test-0.0.1-SNAPSHOT.jar
0 Tue May 29 15:48:00 CST 2018 META-INF/
569 Tue May 29 15:48:00 CST 2018 META-INF/MANIFEST.MF
0 Tue May 29 15:48:00 CST 2018 BOOT-INF/
0 Tue May 29 15:48:00 CST 2018 BOOT-INF/classes/
957 Sun Apr 22 20:21:56 CST 2018 BOOT-INF/classes/Example.class
0 Tue May 29 15:48:00 CST 2018 META-INF/maven/
0 Tue May 29 15:48:00 CST 2018 META-INF/maven/com.example/
0 Tue May 29 15:48:00 CST 2018 META-INF/maven/com.example/my-spring-boot-test/
1083 Sun Apr 22 20:17:34 CST 2018 META-INF/maven/com.example/my-spring-boot-test/pom.xml
131 Tue May 29 15:48:00 CST 2018 META-INF/maven/com.example/my-spring-boot-test/pom.properties
0 Tue May 29 15:48:00 CST 2018 BOOT-INF/lib/
813854 Mon Nov 07 21:16:16 CST 2016 BOOT-INF/lib/spring-web-4.3.4.RELEASE.jar
4597 Mon Apr 04 20:39:24 CST 2016 BOOT-INF/lib/jul-to-slf4j-1.7.21.jar
2295 Tue Nov 08 16:30:36 CST 2016 BOOT-INF/lib/spring-boot-starter-tomcat-1.4.2.RELEASE.jar
704465 Wed Feb 17 16:15:16 CST 2016 BOOT-INF/lib/hibernate-validator-5.2.4.Final.jar
强引用是使用的最普遍的引用类型。如果一个对象具有强引用,那垃圾回收器绝不会回收它。当内存空间不足,Java虚拟机宁愿抛出OutOfMemoryError错误,使程序异常终止,也不会靠随意回收具有强引用的对象来解决内存不足的问题。
//常量池新建一个对象
String str1 = "abc";
//在堆内存中创建String类型,在常量池创建abc对象
String str2 = new String("abc");
//取消引用更需要设置为null
str1 = null;
软引用(softreference)在强度上弱于强引用,通过类SoftReference来表示。当JVM中的内存不足的时候,垃圾回收器会释放那些只被软引用所指向的对象。如果全部释放完这些对象之后,内存还不足,才会抛出OutOfMemory错误。软引用非常适合于创建缓存。当系统内存不足的时候,缓存中的内容是可以被释放的。
//大图片缓存使用软引用
public byte[] getData() {
SoftReference<byte[]> dataRef = new SoftReference<byte[]>(new byte[0]);;
byte[] dataArray = dataRef.get();
if (dataArray == null || dataArray.length == 0) {
dataArray = readImage();
dataRef = new SoftReference<byte[]>(dataArray);
}
return dataArray;
}
在强度上弱于软引用,通过类WeakReference来表示。它的作用是引用一个对象,但是并不阻止该对象被回收。在垃圾回收器运行的时候,如果一个对象的所有引用都是弱引用的话,该对象会被回收。弱引用的作用在于解决强引用所带来的对象之间在存活时间上的耦合关系。 弱引用最常见的用处是在集合类中,尤其在哈希表中。哈希表的接口允许使用任何Java对象作为键来使用。当一个键值对被放入到哈希表中之后,哈希表对象本身就有了对这些键和值对象的引用。如果这种引用是强引用的话,那么只要哈希表对象本身还存活,其中所包含的键和值对象是不会被回收的。如果某个存活时间很长的哈希表中包含的键值对很多,最终就有可能消耗掉JVM中全部的内存。
对于这种情况的解决办法就是使用弱引用来引用这些对象,这样哈希表中的键和值对象都能被垃圾回收。Java中提供了WeakHashMap来满足这一常见需求。引用对象是作为WeakHashMap中的键对象的,当其引用的实际对象被垃圾回收之后,就需要把该键值对从哈希表中删除。
import java.lang.ref.SoftReference;
import java.lang.ref.WeakReference;
import org.junit.Test;
/**
* 软引用影响垃圾回收,但是弱引用不影响垃圾回收
*
* @author resry.lqy
* @version $Id: ReferenceTest.java, v 0.1 2018-06-21 13:37 resry.lqy Exp $
*/
public class ReferenceTest {
@Test
public void test() {
// 在堆内存中创建String类型
String str = new String("abc");
SoftReference<String> srf = new SoftReference<String>(str);
WeakReference<String> wrf = new WeakReference<String>(str);
// 去除强引用
str = null;
// 去除软引用,否则GC无法回收str
srf.clear();
// 软引用影响垃圾回收,但是弱引用不影响垃圾回收
System.gc();
String srfString = srf.get();
String wrfString = wrf.get();
System.out.println("srfString:"+srfString);
System.out.println("wrfString:"+wrfString);
}
}
在Object类里面有个finalize方法,其设计的初衷是在一个对象被真正回收之前,可以用来执行一些清理的工作。但是问题在于垃圾回收器的运行时间是不固定的,所以这些清理工作的实际运行时间也是不能预知的。虚引用(phantom reference)可以解决这个问题。在创建虚引用PhantomReference的时候必须要指定一个引用队列。当一个对象的finalize方法已经被调用了之后,这个对象的虚引用会被加入到队列中。通过检查该队列里面的内容就知道一个对象是不是已经准备要被回收了。(不了解)https://github.com/square/leakcanary 内存泄露检查库是基于此实现的
垃圾回收算法
按照基本回收策略分
引用计数(Reference Counting)
标记-清除(Mark-Sweep)
复制(Copying)
标记-整理(Mark-Compact)
按系统线程分
Phases of CMS
通用优化思路
通过dump内存进行分析,如 jmap -histo:live > histo_live.log 或直接jmap -dump:format=b,file=dump.prof,看看占用内存的主要对象信息,根据代码逻辑来分析,是否有不该存活的对象一直占用了内存
-Xms1700m -Xmx1700m -Xmn680m -Xss256k -XX:PermSize=256m -XX:MaxPermSize=256m
-Xms3800m -Xmx3800m -Xmn1500m -Xss512k -XX:PermSize=256m -XX:MaxPermSize=256m
-XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+CMSClassUnloadingEnabled -XX:+DisableExplicitGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=70 -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=