jvm 优化篇-(1)-StringTable会影响YGC,老铁
2018-09-05 本文已影响0人
tianlang136520
为什么要挖StringTable的坟头?先安无事不好么?
YGC是一个复杂的过程,本就无从下手,凡是能影响YGC性能指标的都尤为吸引人。
线上服务使用CMS回收器,机器配置8c,8g,50g磁盘,启动参数设置如下:
-Xms4g -Xmx4g -XX:PermSize=384m -XX:MaxPermSize=384m -XX:NewSize=3g -XX:MaxNewSize=3g -XX:+UseParNewGC -XX:ParallelGCThreads=8 -XX:MaxTenuringThreshold=5 -XX:+CMSScavengeBeforeRemark -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=60 -XX:CMSFullGCsBeforeCompaction=5 -XX:+CMSClassUnloadingEnabled -XX:CMSInitiatingPermOccupancyFraction=70 -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintReferenceGC -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution -Xloggc:/export/Logs/xx.com/tomcat7-gc.log
这里重点说下新生代3g和触发老年代回收阀值60%,由于老年代1g和阀值60%决定了,当老年代达到600m的时候触发oldgc,无论老年代分配2g也好,阀值就会30%左右,
为啥一定要保证老年代到600m时,触发oldgc?
因为通过监控发现当老年代从0m~600m过程YGC也会受牵连,
为什么极限就是600m呢?
因为600m的时候,YGC刚好过100ms,这是我们部门的标准
如上所说,凡事能影响YGC的内容我们都要进行优化~
StringTable过大会影响YGC,上测试代码:
/**
-XX:+PrintHeapAtGC -XX:+PrintGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC
-XX:CMSInitiatingOccupancyFraction=75
-XX:+UseCMSInitiatingOccupancyOnly -XX:+PrintStringTableStatistics -Xmx1g -Xms1g -Xmn64m
-Xloggc:/Users/xxx/Desktop/gc-log/tomcat7-gc.log
* Created by biudefu on 2018/1/23.
*/
public class TestStringTableStatistics {
private static final int nums = 63600000;
public static void main(String[] args) {
for (int i = 0; i < nums; i++) {
UUID.randomUUID().toString().intern();
if (i >= 100000 && i % 100000 == 0) {
System.out.println("i=" + i);
}
}
}
}
nums =63600000只是我自己随机选取的,足够使用了
摘取tomcat7-gc.log部分日志及监控:
image.png
[GC (Allocation Failure) 52480K->5452K(1042048K), 0.0056730 secs]
[GC (Allocation Failure) 57932K->12675K(1042048K), 0.0394601 secs]
[GC (Allocation Failure) 65155K->19238K(1042048K), 0.0131370 secs]
[GC (Allocation Failure) 71718K->26038K(1042048K), 0.0114077 secs]
...
// 第一次发生oldgc
{Heap before GC invocations=108 (full 0):
par new generation total 59008K, used 59006K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 100% used [0x0000000780000000, 0x0000000783340000, 0x0000000783340000)
from space 6528K, 99% used [0x0000000783340000, 0x000000078399fac0, 0x00000007839a0000)
to space 6528K, 0% used [0x00000007839a0000, 0x00000007839a0000, 0x0000000784000000)
concurrent mark-sweep generation total 983040K, used 727037K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
64.700: [GC (Allocation Failure) 64.700: [ParNew: 59006K->6526K(59008K), 0.1233040 secs] 786044K->740368K(1042048K), 0.1234059 secs] [Times: user=0.90 sys=0.01, real=0.13 secs]
Heap after GC invocations=109 (full 0):
par new generation total 59008K, used 6526K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 0% used [0x0000000780000000, 0x0000000780000000, 0x0000000783340000)
from space 6528K, 99% used [0x00000007839a0000, 0x0000000783fff940, 0x0000000784000000)
to space 6528K, 0% used [0x0000000783340000, 0x0000000783340000, 0x00000007839a0000)
concurrent mark-sweep generation total 983040K, used 733841K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=109 (full 0):
par new generation total 59008K, used 59006K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 100% used [0x0000000780000000, 0x0000000783340000, 0x0000000783340000)
from space 6528K, 99% used [0x00000007839a0000, 0x0000000783fff940, 0x0000000784000000)
to space 6528K, 0% used [0x0000000783340000, 0x0000000783340000, 0x00000007839a0000)
concurrent mark-sweep generation total 983040K, used 733841K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
65.793: [GC (Allocation Failure) 65.793: [ParNew: 59006K->6528K(59008K), 0.1078029 secs] 792848K->747169K(1042048K), 0.1079112 secs] [Times: user=0.82 sys=0.00, real=0.10 secs]
Heap after GC invocations=110 (full 0):
par new generation total 59008K, used 6528K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 0% used [0x0000000780000000, 0x0000000780000000, 0x0000000783340000)
from space 6528K, 100% used [0x0000000783340000, 0x00000007839a0000, 0x00000007839a0000)
to space 6528K, 0% used [0x00000007839a0000, 0x00000007839a0000, 0x0000000784000000)
concurrent mark-sweep generation total 983040K, used 740641K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
}
65.901: [GC (CMS Initial Mark) [1 CMS-initial-mark: 740641K(983040K)] 748218K(1042048K), 0.0008073 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
65.902: [CMS-concurrent-mark-start]
65.909: [CMS-concurrent-mark: 0.007/0.007 secs] [Times: user=0.01 sys=0.01, real=0.00 secs]
65.909: [CMS-concurrent-preclean-start]
65.911: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
65.911: [GC (CMS Final Remark) [YG occupancy: 7577 K (59008 K)]65.911: [Rescan (parallel) , 0.0012025 secs]65.912: [weak refs processing, 0.0000237 secs]65.912: [class unloading, 0.0004845 secs]65.913: [scrub symbol table, 0.0004767 secs]65.913: [scrub string table, 0.7626599 secs][1 CMS-remark: 740641K(983040K)] 748218K(1042048K), 0.7651617 secs] [Times: user=0.76 sys=0.01, real=0.76 secs]
66.676: [CMS-concurrent-sweep-start]
{Heap before GC invocations=110 (full 1):
par new generation total 59008K, used 59008K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 100% used [0x0000000780000000, 0x0000000783340000, 0x0000000783340000)
from space 6528K, 100% used [0x0000000783340000, 0x00000007839a0000, 0x00000007839a0000)
to space 6528K, 0% used [0x00000007839a0000, 0x00000007839a0000, 0x0000000784000000)
concurrent mark-sweep generation total 983040K, used 485613K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
66.837: [GC (Allocation Failure) 66.837: [ParNew: 59008K->6526K(59008K), 0.0103301 secs] 544621K->498816K(1042048K), 0.0104191 secs] [Times: user=0.07 sys=0.00, real=0.01 secs]
Heap after GC invocations=111 (full 1):
par new generation total 59008K, used 6526K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 0% used [0x0000000780000000, 0x0000000780000000, 0x0000000783340000)
from space 6528K, 99% used [0x00000007839a0000, 0x0000000783fffbc0, 0x0000000784000000)
to space 6528K, 0% used [0x0000000783340000, 0x0000000783340000, 0x00000007839a0000)
concurrent mark-sweep generation total 983040K, used 492289K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=111 (full 1):
par new generation total 59008K, used 59006K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 100% used [0x0000000780000000, 0x0000000783340000, 0x0000000783340000)
from space 6528K, 99% used [0x00000007839a0000, 0x0000000783fffbc0, 0x0000000784000000)
to space 6528K, 0% used [0x0000000783340000, 0x0000000783340000, 0x00000007839a0000)
concurrent mark-sweep generation total 983040K, used 212619K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
67.022: [GC (Allocation Failure) 67.022: [ParNew: 59006K->6528K(59008K), 0.0129727 secs] 271626K->225941K(1042048K), 0.0130669 secs] [Times: user=0.08 sys=0.00, real=0.01 secs]
Heap after GC invocations=112 (full 1):
par new generation total 59008K, used 6528K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 0% used [0x0000000780000000, 0x0000000780000000, 0x0000000783340000)
from space 6528K, 100% used [0x0000000783340000, 0x00000007839a0000, 0x00000007839a0000)
to space 6528K, 0% used [0x00000007839a0000, 0x00000007839a0000, 0x0000000784000000)
concurrent mark-sweep generation total 983040K, used 219413K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
}
67.166: [CMS-concurrent-sweep: 0.465/0.489 secs] [Times: user=0.88 sys=0.21, real=0.49 secs]
67.166: [CMS-concurrent-reset-start]
67.169: [CMS-concurrent-reset: 0.004/0.004 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
{Heap before GC invocations=112 (full 1):
par new generation total 59008K, used 59008K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 100% used [0x0000000780000000, 0x0000000783340000, 0x0000000783340000)
from space 6528K, 100% used [0x0000000783340000, 0x00000007839a0000, 0x00000007839a0000)
to space 6528K, 0% used [0x00000007839a0000, 0x00000007839a0000, 0x0000000784000000)
concurrent mark-sweep generation total 983040K, used 14708K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
67.215: [GC (Allocation Failure) 67.215: [ParNew: 59008K->6528K(59008K), 0.0120982 secs] 73716K->28154K(1042048K), 0.0121907 secs] [Times: user=0.09 sys=0.01, real=0.01 secs]
Heap after GC invocations=113 (full 1):
par new generation total 59008K, used 6528K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 0% used [0x0000000780000000, 0x0000000780000000, 0x0000000783340000)
from space 6528K, 100% used [0x00000007839a0000, 0x0000000784000000, 0x0000000784000000)
to space 6528K, 0% used [0x0000000783340000, 0x0000000783340000, 0x00000007839a0000)
concurrent mark-sweep generation total 983040K, used 21626K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
}
{Heap before GC invocations=113 (full 1):
par new generation total 59008K, used 59008K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 100% used [0x0000000780000000, 0x0000000783340000, 0x0000000783340000)
from space 6528K, 100% used [0x00000007839a0000, 0x0000000784000000, 0x0000000784000000)
to space 6528K, 0% used [0x0000000783340000, 0x0000000783340000, 0x00000007839a0000)
concurrent mark-sweep generation total 983040K, used 21626K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
67.413: [GC (Allocation Failure) 67.413: [ParNew: 59008K->6528K(59008K), 0.0145553 secs] 80634K->34913K(1042048K), 0.0146502 secs] [Times: user=0.11 sys=0.00, real=0.01 secs]
Heap after GC invocations=114 (full 1):
par new generation total 59008K, used 6528K [0x0000000780000000, 0x0000000784000000, 0x0000000784000000)
eden space 52480K, 0% used [0x0000000780000000, 0x0000000780000000, 0x0000000783340000)
from space 6528K, 100% used [0x0000000783340000, 0x00000007839a0000, 0x00000007839a0000)
to space 6528K, 0% used [0x00000007839a0000, 0x00000007839a0000, 0x0000000784000000)
concurrent mark-sweep generation total 983040K, used 28385K [0x0000000784000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 3619K, capacity 4540K, committed 4864K, reserved 1056768K
class space used 403K, capacity 428K, committed 512K, reserved 1048576K
}
通过日志能发现oldgc 发生前yonggc一次已经到100+ms了,而当oldgc发生完毕后,yonggc平均又开始在10ms左右。老年代内存由740641K---> 219413K,回收率高达72%。这就不得不深究下stringtable在jvm内存分配中处于什么角色。
针对JVM启动参数中的这二位做下介绍:
-XX:StringTableSize
含义:配置字符串常量池中的StringTable大小,默认:60013 (Number of buckets in the interned String table) ,StringTable数据结构是hashtable,这个值就是hashtable的size大小,建议设置成大一点的质数
-XX:+PrintStringTableStatistics
含义:在JVM进程退出时,打印出StringTable的统计信息输出到gclog中.