高手的存在,就是让服务10亿人的时候,你感觉只是为你一个人服务......

GC combination test

目录
  1. 1. JVM GC组合方式
  2. 2. 测试一:单个方法测试
    1. 2.1. 测试代码
    2. 2.2. -XX:+UseSerialGC
    3. 2.3. -XX:+UseParallelGC
    4. 2.4. -XX:+UseParallelOldGC
    5. 2.5. -XX:+UseParNewGC
    6. 2.6. -XX:+UseConeMarkSweepGC
  3. 3. 测试二:搜索应用调用接口
    1. 3.1. 搜索系统机器及jdk情况
    2. 3.2. 接口与测试脚本
    3. 3.3. -XX:+UseSerialGC
    4. 3.4. -XX:+UseParallelGC
    5. 3.5. -XX:+UseParallelOldGC
    6. 3.6. -XX:+UseParNewGC
    7. 3.7. -XX:+UseConeMarkSweepGC

不同的垃圾收集器对系统有不同的性能表现,没有哪种垃圾收集器可以完美匹配所有系统。

生产环境中需要针对不同的应用系统,进行不断的测试,尽可能选择适当的垃圾回收器与gc参数。

所以,对于某个业务系统来说,没有最佳的GC组合,只有最合适的GC组合。


JVM GC组合方式

Java的gc回收参数有XX:+UseSerialGC,XX:+UseConcMarkSweepGC,XX:+UseParNewGC,XX:+UseParallelGC,XX:+UseParallelOldGC等
Alt text

几个参数是如何搭配的,jvm代码写的非常清楚:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
bool Arguments::check_gc_consistency() {  
bool status = true;
// Ensure that the user has not selected conflicting sets
// of collectors. [Note: this check is merely a user convenience;
// collectors over-ride each other so that only a non-conflicting
// set is selected; however what the user gets is not what they
// may have expected from the combination they asked for. It's
// better to reduce user confusion by not allowing them to
// select conflicting combinations.
uint i = 0;
if (UseSerialGC) i++;
if (UseConcMarkSweepGC || UseParNewGC) i++;
if (UseParallelGC || UseParallelOldGC) i++;
if (UseG1GC) i++;
if (i > 1) {
jio_fprintf(defaultStream::error_stream(),
"Conflicting collector combinations in option list; "
"please refer to the release notes for the combinations "
"allowed\n");

status = false;
}

return status;
}

这里先不考虑G1的情况,将其分成5种进行测试:
-XX:+UseSerialGC
yong:串行GC
old:串行GC

-XX:+UseParallelGC
yong:并行回收GC
old:串行GC

-XX:+UseConeMarkSweepGC
yong:并行GC
old:并发GC

-XX:+UseParNewGC
yong:并行GC
old:串行GC

-XX:+UseParallelOldGC
yong:并行回收GC
old:并行GC

关于垃圾收集器基础知识,可以参考“浅谈jvm垃圾收集器


测试一:单个方法测试

使用本地机器进行测试:
JVM: Java HotSpot(TM) Client VM (16.3-b01, mixed mode, sharing)
Java: version 1.6.0_20, vendor Sun Microsystems Inc.

windows 7
Alt text

测试代码

每次分配 512*100B 空间,循环1W次。
固定参数:-Xmx512M -Xms512M,采用不同的垃圾回收器,输出程序运行所消耗的时间。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
import java.util.HashMap;

/**
* GCTimeTest.java
*
* @author lit
*/

public class GCTimeTest {

static HashMap map = new HashMap();

public static void main(String[] args) throws InterruptedException {

Thread.sleep(60000);

long begintime = System.currentTimeMillis();
for (int i = 0; i < 10000; i++) {
if (map.size() * 512 / 1024 / 1024 >= 400) {
map.clear();// 保护内存不溢出
}
byte[] b1;
for (int j = 0; j < 100; j++) {
b1 = new byte[512];
map.put(System.nanoTime(), b1);// 不断消耗内存
}
}
long endtime = System.currentTimeMillis();
System.out.println("cost time:" + (endtime - begintime));
}

}

-XX:+UseSerialGC

yong:串行GC
old:串行GC
VM arguments:-Xmx512M -Xms512M -XX:+UseSerialGC -Xloggc:C:/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

运行结果:
cost time:2915

GC日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
60.429: [GC 60.429: [DefNew
Desired survivor size 8945664 bytes, new threshold 1 (max 15)
- age 1: 17891320 bytes, 17891320 total
: 139776K->17471K(157248K), 0.3461929 secs] 139776K->136930K(506816K), 0.3462939 secs] [Times: user=0.20 sys=0.13, real=0.35 secs]
60.982: [GC 60.982: [DefNew
Desired survivor size 8945664 bytes, new threshold 1 (max 15)
- age 1: 17891328 bytes, 17891328 total
: 157247K->17472K(157248K), 0.4087474 secs] 276706K->274374K(506816K), 0.4088472 secs] [Times: user=0.25 sys=0.11, real=0.41 secs]
61.563: [GC 61.563: [DefNew: 157248K->157248K(157248K), 0.0000115 secs]61.563: [Tenured: 256902K->349567K(349568K), 0.7434672 secs] 414150K->413941K(506816K), [Perm : 374K->374K(12288K)], 0.7436129 secs] [Times: user=0.64 sys=0.08, real=0.74 secs]
62.743: [Full GC 62.743: [Tenured: 349567K->48225K(349568K), 0.2319682 secs] 506815K->48225K(506816K), [Perm : 374K->374K(12288K)], 0.2320699 secs] [Times: user=0.23 sys=0.00, real=0.23 secs]
Heap
def new generation total 157248K, used 74536K [0x129e0000, 0x1d480000, 0x1d480000)
eden space 139776K, 53% used [0x129e0000, 0x172aa230, 0x1b260000)
from space 17472K, 0% used [0x1b260000, 0x1b260000, 0x1c370000)
to space 17472K, 0% used [0x1c370000, 0x1c370000, 0x1d480000)
tenured generation total 349568K, used 48225K [0x1d480000, 0x329e0000, 0x329e0000)
the space 349568K, 13% used [0x1d480000, 0x20398700, 0x20398800, 0x329e0000)
compacting perm gen total 12288K, used 374K [0x329e0000, 0x335e0000, 0x369e0000)
the space 12288K, 3% used [0x329e0000, 0x32a3d840, 0x32a3da00, 0x335e0000)
ro space 10240K, 54% used [0x369e0000, 0x36f5b760, 0x36f5b800, 0x373e0000)
rw space 12288K, 55% used [0x373e0000, 0x37a7f798, 0x37a7f800, 0x37fe0000)

从日志中看到:
Desired survivor size 8945664 bytes,8945664 bytes 其实是单个survivor区的一半大小,
-XX:TargetSurvivorRatio=50 有这么个参数,默认survivor 区到50%使用,就把对象晋升old

GC日志分析:
Alt text
Alt text


-XX:+UseParallelGC

yong:并行回收GC
old:串行GC
VM arguments:-Xmx512M -Xms512M -XX:+UseParallelGC -Xloggc:C:/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

线程数默认为CPU个数,CPU很多时,可用–XX:ParallelGCThreads=线程数。
这次使用默认值,2核cpu

运行结果:
cost time:2808

GC日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
60.506: [GC
Desired survivor size 22347776 bytes, new threshold 7 (max 15)
[PSYoungGen: 131072K->21816K(152896K)] 131072K->132212K(502464K), 0.2156646 secs] [Times: user=0.33 sys=0.05, real=0.22 secs]
60.936: [GC
Desired survivor size 22347776 bytes, new threshold 7 (max 15)
[PSYoungGen: 152888K->21808K(152896K)] 263284K->264668K(502464K), 0.3085561 secs] [Times: user=0.39 sys=0.02, real=0.31 secs]
61.244: [Full GC [PSYoungGen: 21808K->0K(152896K)] [PSOldGen: 242860K->264149K(349568K)] 264668K->264149K(502464K) [PSPermGen: 2099K->2099K(12288K)], 0.4015657 secs] [Times: user=0.36 sys=0.03, real=0.40 secs]
61.826: [Full GC [PSYoungGen: 131072K->45522K(152896K)] [PSOldGen: 264149K->349568K(349568K)] 395221K->395090K(502464K) [PSPermGen: 2099K->2099K(12288K)], 0.7014297 secs] [Times: user=0.70 sys=0.00, real=0.70 secs]
62.755: [Full GC [PSYoungGen: 131072K->0K(152896K)] [PSOldGen: 349568K->14857K(349568K)] 480640K->14857K(502464K) [PSPermGen: 2099K->2099K(12288K)], 0.1491931 secs] [Times: user=0.16 sys=0.00, real=0.15 secs]
Heap
PSYoungGen total 152896K, used 96649K [0x1db10000, 0x285b0000, 0x285b0000)
eden space 131072K, 73% used [0x1db10000,0x23972778,0x25b10000)
from space 21824K, 0% used [0x27060000,0x27060000,0x285b0000)
to space 21824K, 0% used [0x25b10000,0x25b10000,0x27060000)
PSOldGen total 349568K, used 14857K [0x085b0000, 0x1db10000, 0x1db10000)
object space 349568K, 4% used [0x085b0000,0x094325a0,0x1db10000)
PSPermGen total 12288K, used 2104K [0x045b0000, 0x051b0000, 0x085b0000)
object space 12288K, 17% used [0x045b0000,0x047be2f8,0x051b0000)

GC日志分析:

Alt text

Alt text


-XX:+UseParallelOldGC

yong:并行回收GC
old:并行GC
VM arguments:-Xmx512M -Xms512M -XX:+UseParallelOldGC -Xloggc:C:/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

运行结果:
cost time:2564

GC日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
60.353: [GC
Desired survivor size 22347776 bytes, new threshold 7 (max 15)
[PSYoungGen: 131072K->21816K(152896K)] 131072K->132224K(502464K), 0.1793418 secs] [Times: user=0.30 sys=0.06, real=0.18 secs]
60.741: [GC
Desired survivor size 22347776 bytes, new threshold 7 (max 15)
[PSYoungGen: 152888K->21808K(152896K)] 263296K->264672K(502464K), 0.2304476 secs] [Times: user=0.42 sys=0.05, real=0.23 secs]
60.971: [Full GC [PSYoungGen: 21808K->0K(152896K)] [ParOldGen: 242864K->257034K(349568K)] 264672K->257034K(502464K) [PSPermGen: 2099K->2098K(12288K)], 0.5450639 secs] [Times: user=0.97 sys=0.00, real=0.55 secs]
61.671: [Full GC [PSYoungGen: 131072K->38264K(152896K)] [ParOldGen: 257034K->349567K(349568K)] 388106K->387831K(502464K) [PSPermGen: 2098K->2098K(12288K)], 0.6697351 secs] [Times: user=1.18 sys=0.03, real=0.67 secs]
62.593: [Full GC [PSYoungGen: 131072K->0K(152896K)] [ParOldGen: 349567K->22005K(349568K)] 480639K->22005K(502464K) [PSPermGen: 2098K->2098K(12288K)], 0.0589215 secs] [Times: user=0.06 sys=0.00, real=0.06 secs]
Heap
PSYoungGen total 152896K, used 89296K [0x1da20000, 0x284c0000, 0x284c0000)
eden space 131072K, 68% used [0x1da20000,0x23154358,0x25a20000)
from space 21824K, 0% used [0x26f70000,0x26f70000,0x284c0000)
to space 21824K, 0% used [0x25a20000,0x25a20000,0x26f70000)
ParOldGen total 349568K, used 22005K [0x084c0000, 0x1da20000, 0x1da20000)
object space 349568K, 6% used [0x084c0000,0x09a3d470,0x1da20000)
PSPermGen total 12288K, used 2103K [0x044c0000, 0x050c0000, 0x084c0000)
object space 12288K, 17% used [0x044c0000,0x046cdfd0,0x050c0000)

GC日志分析:
+UseParallelOldGC与 -XX:+UseParallelGC 的GC日志中,full gc收集打出来的:ParOldGen与PSOldGen
jvm具体怎么给它们起名的呢?

1
2
3
inline const char* PSOldGen::select_name() {  
return UseParallelOldGC ? "ParOldGen" : "PSOldGen";
}

Alt text

Alt text


-XX:+UseParNewGC

yong:并行GC
old:串行GC
VM arguments:-Xmx512M -Xms512M -XX:+UseParNewGC -Xloggc:C:/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

运行结果:
cost time:2174

GC日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
60.370: [GC 60.370: [ParNew
Desired survivor size 8945664 bytes, new threshold 1 (max 15)
- age 1: 17880440 bytes, 17880440 total
: 139776K->17471K(157248K), 0.2069423 secs] 139776K->137270K(506816K), 0.2070873 secs] [Times: user=0.37 sys=0.03, real=0.21 secs]
60.771: [GC 60.771: [ParNew
Desired survivor size 8945664 bytes, new threshold 1 (max 15)
- age 1: 17890544 bytes, 17890544 total
: 157247K->17472K(157248K), 0.2407578 secs] 277046K->274774K(506816K), 0.2408691 secs] [Times: user=0.36 sys=0.11, real=0.24 secs]
61.178: [GC 61.178: [ParNew: 157248K->157248K(157248K), 0.0000106 secs]61.178: [Tenured: 257302K->349567K(349568K), 0.6391748 secs] 414550K->414275K(506816K), [Perm : 2099K->2099K(12288K)], 0.6394751 secs] [Times: user=0.55 sys=0.08, real=0.64 secs]
62.010: [Full GC 62.010: [Tenured: 349567K->47934K(349568K), 0.1982086 secs] 506815K->47934K(506816K), [Perm : 2099K->2099K(12288K)], 0.1983080 secs] [Times: user=0.19 sys=0.00, real=0.20 secs]
Heap
par new generation total 157248K, used 74536K [0x04680000, 0x0f120000, 0x0f120000)
eden space 139776K, 53% used [0x04680000, 0x08f4a230, 0x0cf00000)
from space 17472K, 0% used [0x0cf00000, 0x0cf00000, 0x0e010000)
to space 17472K, 0% used [0x0e010000, 0x0e010000, 0x0f120000)
tenured generation total 349568K, used 47934K [0x0f120000, 0x24680000, 0x24680000)
the space 349568K, 13% used [0x0f120000, 0x11fefa20, 0x11fefc00, 0x24680000)
compacting perm gen total 12288K, used 2104K [0x24680000, 0x25280000, 0x28680000)
the space 12288K, 17% used [0x24680000, 0x2488e2f8, 0x2488e400, 0x25280000)
No shared spaces configured.

GC日志分析:
Alt text

Alt text


-XX:+UseConeMarkSweepGC

yong:并行GC
old:并发GC
VM arguments:-Xmx512M -Xms512M -XX:+UseConcMarkSweepGC-Xloggc:C:/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

运行结果:
cost time:2039

GC日志:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
60.170: [GC 60.197: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3339744 bytes, 3339744 total
: 26240K->3264K(29504K), 0.0394432 secs] 26240K->25941K(521024K), 0.0668760 secs] [Times: user=0.08 sys=0.00, real=0.07 secs]
60.265: [GC 60.266: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341880 bytes, 3341880 total
: 29504K->3264K(29504K), 0.0446892 secs] 52181K->51634K(521024K), 0.0448031 secs] [Times: user=0.08 sys=0.00, real=0.05 secs]
60.341: [GC 60.341: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341296 bytes, 3341296 total
: 29504K->3264K(29504K), 0.0445981 secs] 77874K->77169K(521024K), 0.0447130 secs] [Times: user=0.06 sys=0.02, real=0.05 secs]
60.415: [GC 60.415: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341056 bytes, 3341056 total
: 29504K->3264K(29504K), 0.0451765 secs] 103409K->103252K(521024K), 0.0452811 secs] [Times: user=0.08 sys=0.01, real=0.05 secs]
60.499: [GC 60.499: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341104 bytes, 3341104 total
: 29504K->3264K(29504K), 0.0508932 secs] 129492K->129371K(521024K), 0.0510638 secs] [Times: user=0.08 sys=0.02, real=0.05 secs]
60.585: [GC 60.585: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3342192 bytes, 3342192 total
: 29504K->3264K(29504K), 0.0498377 secs] 155611K->155532K(521024K), 0.0499417 secs] [Times: user=0.11 sys=0.00, real=0.05 secs]
60.671: [GC 60.671: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341912 bytes, 3341912 total
: 29504K->3264K(29504K), 0.0577586 secs] 181772K->181698K(521024K), 0.0578414 secs] [Times: user=0.09 sys=0.00, real=0.06 secs]
60.765: [GC 60.765: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340400 bytes, 3340400 total
: 29504K->3262K(29504K), 0.0496591 secs] 207938K->207908K(521024K), 0.0497575 secs] [Times: user=0.09 sys=0.00, real=0.05 secs]
60.864: [GC 60.864: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340104 bytes, 3340104 total
: 29502K->3262K(29504K), 0.0542709 secs] 234148K->234095K(521024K), 0.0543777 secs] [Times: user=0.09 sys=0.02, real=0.06 secs]
60.949: [GC 60.949: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3342024 bytes, 3342024 total
: 29502K->3264K(29504K), 0.0494512 secs] 260335K->260265K(521024K), 0.0495500 secs] [Times: user=0.08 sys=0.00, real=0.05 secs]
60.999: [GC [1 CMS-initial-mark: 257001K(491520K)] 260796K(521024K), 0.0020226 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
61.001: [CMS-concurrent-mark-start]
61.036: [GC 61.036: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341424 bytes, 3341424 total
: 29504K->3263K(29504K), 0.0523987 secs] 286505K->286469K(521024K), 0.0525158 secs] [Times: user=0.09 sys=0.01, real=0.05 secs]
61.129: [GC 61.129: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340472 bytes, 3340472 total
: 29503K->3263K(29504K), 0.0545435 secs] 312709K->312686K(521024K), 0.0546507 secs] [Times: user=0.08 sys=0.00, real=0.05 secs]
61.217: [GC 61.217: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340400 bytes, 3340400 total
: 29503K->3262K(29504K), 0.0538670 secs] 338926K->338901K(521024K), 0.0539802 secs] [Times: user=0.08 sys=0.02, real=0.05 secs]
61.304: [GC 61.304: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340448 bytes, 3340448 total
: 29502K->3262K(29504K), 0.0626886 secs] 365141K->365119K(521024K), 0.0628105 secs] [Times: user=0.09 sys=0.01, real=0.06 secs]
61.399: [GC 61.399: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340376 bytes, 3340376 total
: 29502K->3262K(29504K), 0.0529716 secs] 391359K->391340K(521024K), 0.0530862 secs] [Times: user=0.05 sys=0.02, real=0.05 secs]
61.496: [GC 61.496: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3339856 bytes, 3339856 total
: 29502K->3262K(29504K), 0.0532713 secs] 417580K->417553K(521024K), 0.0533851 secs] [Times: user=0.05 sys=0.05, real=0.05 secs]
61.584: [GC 61.584: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341616 bytes, 3341616 total
: 29502K->3264K(29504K), 0.0529081 secs] 443793K->443772K(521024K), 0.0530188 secs] [Times: user=0.11 sys=0.00, real=0.05 secs]
61.703: [GC 61.703: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3341080 bytes, 3341080 total
: 29504K->3262K(29504K), 0.0667567 secs] 470012K->469993K(521024K), 0.0668709 secs] [Times: user=0.12 sys=0.00, real=0.07 secs]
61.801: [GC 61.801: [ParNew: 29502K->29502K(29504K), 0.0000183 secs]61.801: [CMS61.825: [CMS-concurrent-mark: 0.371/0.824 secs] [Times: user=1.37 sys=0.11, real=0.82 secs]
(concurrent mode failure): 466731K->34165K(491520K), 0.2074614 secs] 496233K->34165K(521024K), [CMS Perm : 2099K->2098K(12288K)], 0.2076597 secs] [Times: user=0.22 sys=0.00, real=0.21 secs]
62.036: [GC 62.036: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340808 bytes, 3340808 total
: 26240K->3262K(29504K), 0.0378126 secs] 60405K->60677K(521024K), 0.0379156 secs] [Times: user=0.08 sys=0.00, real=0.04 secs]
62.101: [GC 62.101: [ParNew
Desired survivor size 1671168 bytes, new threshold 1 (max 4)
- age 1: 3340448 bytes, 3340448 total
: 29502K->3262K(29504K), 0.0443056 secs] 86917K->86944K(521024K), 0.0444194 secs] [Times: user=0.06 sys=0.00, real=0.04 secs]
Heap
par new generation total 29504K, used 24613K [0x04650000, 0x06650000, 0x06650000)
eden space 26240K, 81% used [0x04650000, 0x05b29da8, 0x05ff0000)
from space 3264K, 99% used [0x05ff0000, 0x0631fa50, 0x06320000)
to space 3264K, 0% used [0x06320000, 0x06320000, 0x06650000)
concurrent mark-sweep generation total 491520K, used 83682K [0x06650000, 0x24650000, 0x24650000)
concurrent-mark-sweep perm gen total 12288K, used 2103K [0x24650000, 0x25250000, 0x28650000)

GC日志分析:

Alt text
Alt text

关于cms的日志分析,有一篇很好的文章,写的很详细。
http://www.cnblogs.com/zhangxiaoguang/p/5792468.html


从上面的测试结果来看,采用不同的gc收集器,默认情况对yong区、old区内存大小的分配不一样,
gc日志的格式有一些差异,最重要的一点是对于代码段的整体执行时间有一定影响。


测试二:搜索应用调用接口

上面的测试是对单个方法、短时间的测试,
下面对搜索系统的两个搜索接口做压力测试,持续20分钟。

搜索系统机器及jdk情况

CPU: 8核 Intel(R) Xeon(R) CPU E5410 @ 2.33GHz
MEM: 10G

JDK版本:

java version “1.7.0_40”
Java(TM) SE Runtime Environment (build 1.7.0_40-b43)
Java HotSpot(TM) 64-Bit Server VM (build 24.0-b56, mixed mode)


接口与测试脚本

两个接口:

/suggest/pressSuggestTest.do 搜索建议词
/suggest/pressSpellCheckTest.do 搜索词纠错

loadrunner脚本:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
lr_start_transaction("pressSuggestTest");

web_reg_find("Search=All",
"Text=200 OK",
LAST);

web_url("pressSuggestTest.do",
"URL=http://192.168.52.170:82/suggest/pressSuggestTest.do",
"Resource=0",
"Referer=",
"Snapshot=t5.inf",
LAST);


lr_end_transaction("pressSuggestTest", LR_AUTO);


lr_start_transaction("pressSpellCheckTest");

web_reg_find("Search=All",
"Text=200 OK",
LAST);

web_url("pressSuggestTest.do",
"URL=http://192.168.52.170:82/suggest/pressSpellCheckTest.do",
"Resource=0",
"Referer=",
"Snapshot=t5.inf",
LAST);


lr_end_transaction("pressSpellCheckTest", LR_AUTO);


以下测试并发用户均为20个,持续时间20分钟

-XX:+UseSerialGC

yong:串行GC
old:串行GC
VM arguments:-Xms1800m -Xmx1800m -Xmn800m -XX:PermSize=250m -XX:MaxPermSize=250m -Xss2m -XX:+UseSerialGC -J-Xloggc:/var/log/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution
Alt text

测试结果:

QPS:797
Alt text
[QPS波动,比较平稳]

Throughput : 90.765%
Latency: Avg GC Time 26 ms ,Max GC Time 6 sec 650 ms
GC total time:Minor GC total time 1 min 13 sec 58 ms,Full GC total time 1 min 930 ms

GC日志分析:
Alt text


-XX:+UseParallelGC

yong:串行GC
old:串行GC
VM arguments:-Xms1800m -Xmx1800m -Xmn800m -XX:PermSize=250m -XX:MaxPermSize=250m -Xss2m -XX:+UseParallelGC -J-Xloggc:/var/log/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

Alt text

测试结果:
QPS:837
Alt text
[QPS波动,比较平稳]

Throughput : 95.59%
Latency: Avg GC Time 16 ms,Max GC Time 5 sec 560 ms
GC total time:Minor GC total time 52 sec 907 ms,Full GC total time 18 sec 99 ms

GC日志分析:
Alt text


-XX:+UseParallelOldGC

yong:串行GC
old:串行GC
VM arguments:-Xms1800m -Xmx1800m -Xmn800m -XX:PermSize=250m -XX:MaxPermSize=250m -Xss2m -XX:+UseParallelOldGC -J-Xloggc:/var/log/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution
Alt text

这边需要着重讲一下ParallelGC与ParallelOldGC 在jmap -heap命令的显示,
仔细看yong和old区generation显示的信息:
Alt text

ParallelGC与ParallelOldGC 都这样显示的,原本以为ParallelGC的old也是并行收集,
但是看到下面的帖子才明白,ParallelGC的old区确实是串行收集,挺混乱的~
http://hllvm.group.iteye.com/group/topic/27629

测试结果:

QPS:849
Alt text

[QPS波动,比较平稳]

Throughput : 95.372%
Latency: Avg GC Time 16 ms,Max GC Time 4 sec 830 ms
GC total time:Minor GC total time 53 sec 857 ms,Full GC total time 16 sec 255 ms

GC日志分析:
Alt text


-XX:+UseParNewGC

yong:串行GC
old:串行GC
VM arguments:-Xms1800m -Xmx1800m -Xmn800m -XX:PermSize=250m -XX:MaxPermSize=250m -Xss2m -XX:+UseParNewGC -J-Xloggc:/var/log/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution
Alt text

测试结果:

QPS:781
Alt text
[QPS波动]

Throughput : 89.839%
Latency: Avg GC Time 27 ms,Max GC Time 6 sec 540 ms
GC total time:Minor GC total time 59 sec 257 ms,Full GC total time 1 min 24 sec 420 ms

GC日志分析:
Alt text


-XX:+UseConeMarkSweepGC

yong:串行GC
old:串行GC
VM arguments:-Xms1800m -Xmx1800m -Xmn800m -XX:PermSize=250m -XX:MaxPermSize=250m -Xss2m -XX:+UseConcMarkSweepGC -J-Xloggc:/var/log/gc_product.log -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTenuringDistribution

Alt text

测试结果:

QPS:746
Alt text
[QPS波动,很平稳]

Throughput : 93.962%
Latency: Avg GC Time 20 ms,Max GC Time 7 sec 400 ms
GC total time:Minor GC total time 49 sec 118 ms,Full GC total time 48 sec 700 ms

GC日志分析:
Alt text


把上面的测试结果汇总一下,重点关注Throughput 与 Latency:

参数 QPS Throughput Latency GC total time
-XX:+UseSerialGC 797 90.765% Avg GC Time 26ms ,Max GC Time 6sec650ms Minor GC total time 1min13sec58ms,Full GC total time 1min930ms
-XX:+UseParallelGC 837 95.59% Avg GC Time 16ms,Max GC Time 5sec560ms Minor GC total time 52 sec907ms,Full GC total time 18sec99ms
-XX:+UseParallelOldGC 849 95.372% Avg GC Time 16 ms,Max GC Time 4sec830ms Minor GC total time 53 sec857ms,Full GC total time 16sec255ms
-XX:+UseParNewGC 781 89.839% Avg GC Time 27ms,Max GC Time 6sec540ms Minor GC total time 59 sec257ms,Full GC total time 1 min24sec420ms
-XX:+UseConeMarkSweepGC 746 93.962% Avg GC Time 20ms,Max GC Time 7sec400ms Minor GC total time 49 sec118ms,Full GC total time 48 sec700ms

单从上面的测试结果来看,-XX:+UseParallelOldGC的效果最好。

这只是一个简单的例子,gc收集器选择的过程远不止这些。