IT博客汇 | 对HotSpot JVM中String对象的分析

对HotSpot JVM中String对象的分析

longhao (longtask@gmail.com)发表于 2011-06-15 03:21:07

和涛哥讨论如何证明HotSpot JVM的String pool在Perm Gen的问题，写了点代码，加了个String.intern()，然后用jconsole跟踪查看了下Perm Gen的内存使用情况，发现有一个增长曲线，后面觉得这个就是对的了。我也把结论发到了新浪微博上：

今天同事手动证明了java string pools是放在perm size中，推理的过程也有很多东西可以学习

在sina微薄上得到了@RednaxelaFX 同学的回复，提出了一些质疑。具体内容如下：

回复@hoorace: 呵呵。String.intern()发现传进来的参数在字符串池里已存在就不会往PermGen里放新数据。为了看到PermGen使用量上升需要不断用内容不同的String调用intern()。但创建出内容不同的String实例势必会增加普通Java堆的使用量。这样，实验过程中就会看到两边都在涨。不知你们如何分析这点的呢？ (6月13日 19:00)

jconsole是提供了只看PermGen的视图。但这正是我想指出的方法上应该注意的点：你们的实验可以观察到两边的内存占用量都在增长，这时如果只看其中一侧就导出结论，无疑从方法上有误；这样得出的结论即便能用于解释现象也仍然是不可靠的。需要正确的、确凿的证据和推导过程，结论才有意义。 (6月13日 22:59)

后来在旺旺上找 @RednaxelaFX 同学聊天，至少发现测试过程中的以下问题：

一开始做出的假设不够，例如：如果对象直接写道 Old Gen怎么办(设置-XX:PretenureSizeThreshold=1024)？
需要同事观察heap 和 non-heap中的内存使用变化情况；
排除JVM生成的其他对象对测试的干扰；
jconsole查看执行情况需要JMX支持，对测试的显示曲线的影响。

第一次测试：new String("xx") + string.intern

测试的java代码每次都生成新的字符串，测试一下new String("") 和 string.intern()在JVM内存中使用情况。Java代码如下：

import java.util.Random;

public class StringTest {
private static final String template = "ABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789abcdefghijklmnopqrstuvwxyz";
private static Random randGen = new Random();
private static final char[] numbersAndLetters = template.toCharArray();
private static final int length = 32768;
private static char[] randBuffer = new char[length];

public static String randomString() {
for (int i = 0; i < randBuffer.length; i++) {
randBuffer[i] = numbersAndLetters[randGen.nextInt(template.length())];
}

return new String(randBuffer);
}

public static void testStringPoolInPerm() {
while(true) {
String str = randomString();
if(str == null) {
return;
}
str.intern();
try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
return;
}
}
}

public static void testAllocInHeap() {
while(true) {
String str = randomString();
if(str == null) {
return;
}

try {
Thread.sleep(100);
} catch (InterruptedException e) {
e.printStackTrace();
return;
}
}
}

public static void main(String[] args) {
Thread t1 = new Thread(new Runnable(){
public void run(){
StringTest2.testAllocInHeap();
}
});
Thread t2 = new Thread(new Runnable(){
public void run(){
StringTest2.testStringPoolInPerm();
}
});
t1.start();
t2.start();
}

}

编译代码并执行：

longhao@longhao-desktop:/mnt/test$ javac StringTest.java
longhao@longhao-desktop:/mnt/test$ java -Xms128M -Xmx128M -Xmn64m -XX:PermSize=64M -XX:MaxPermSize=64M -verbose:gc -XX:+PrintGCDetails -Dcom.sun.management.jmxremote -XX:+DoEscapeAnalysis -XX:+EliminateAllocations StringTest

启动jconsole查看内存使用情况，得到的Eden 和 Perm的使用情况如下：

展示的内存使用情况基本是平滑的曲线，第一个图仅仅打开了向Eden写数据的线程，第二个图打开了写Eden和Perm两个地方的

GC日志如下：

[GC [PSYoungGen: 49090K->528K(57344K)] 49090K->528K(122880K), 0.0166390 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
[GC [PSYoungGen: 49649K->520K(57344K)] 49649K->520K(122880K), 0.0013780 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 28526K->584K(57344K)] 28526K->584K(122880K), 0.0012440 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC [PSYoungGen: 584K->0K(57344K)] [PSOldGen: 0K->562K(65536K)] 584K->562K(122880K) [PSPermGen: 65490K->5101K(65536K)], 0.0129200 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC [PSYoungGen: 49096K->80K(57344K)] 49659K->642K(122880K), 0.0008290 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 49216K->80K(57344K)] 49778K->642K(122880K), 0.0005290 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 22805K->144K(64768K)] 23367K->706K(130304K), 0.0007600 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC [PSYoungGen: 144K->0K(64768K)] [PSOldGen: 562K->690K(65536K)] 706K->690K(130304K) [PSPermGen: 65491K->5102K(65536K)], 0.0121160 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC [PSYoungGen: 63945K->80K(64768K)] 64635K->770K(130304K), 0.0005190 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 57126K->144K(64768K)] 57816K->834K(130304K), 0.0006330 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC [PSYoungGen: 144K->0K(64768K)] [PSOldGen: 690K->818K(65536K)] 834K->818K(130304K) [PSPermGen: 65491K->5102K(65536K)], 0.0121630 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC [PSYoungGen: 63997K->80K(64768K)] 64815K->898K(130304K), 0.0004880 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 57061K->144K(64832K)] 57880K->962K(130368K), 0.0007720 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC [PSYoungGen: 144K->0K(64832K)] [PSOldGen: 818K->530K(65536K)] 962K->530K(130368K) [PSPermGen: 65491K->5021K(65536K)], 0.0152100 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC [PSYoungGen: 64127K->80K(64832K)] 64657K->610K(130368K), 0.0005020 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 57052K->144K(64896K)] 57582K->674K(130432K), 0.0006050 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC [PSYoungGen: 144K->0K(64896K)] [PSOldGen: 530K->658K(65536K)] 674K->658K(130432K) [PSPermGen: 65475K->5022K(65536K)], 0.0117410 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[GC [PSYoungGen: 64185K->80K(64832K)] 64843K->738K(130368K), 0.0004910 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[GC [PSYoungGen: 56903K->144K(64896K)] 57561K->802K(130432K), 0.0008360 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
[Full GC [PSYoungGen: 144K->0K(64896K)] [PSOldGen: 658K->786K(65536K)] 802K->786K(130432K) [PSPermGen: 65475K->5022K(65536K)], 0.0126470 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

在Eden写满的时候，会做一次Minor GC，在Perm写满的时候会做Full GC。

由于 @RednaxelaFX 同学说Jconsole测试使用了JMX，会影响测试结果，建议使用jstat，得到的结果是一样的。

> jps 找到你的java执行类
> jstat -gcutil 10265(pid) 500 > gclog.txt &
> tail -f gclog.txt

后来看到《请别再拿“String s = new String("xyz");创建了多少个String实例”来面试了吧》博文，觉得有必要用截取固定字符串测试一下

测试第二次：固定内容的string.substring()

继续测试代码：（注意替换2056个英文字符）

import java.util.Random;

public class StringTest {
public static final String str = "xxx";//请使用2056个以上的字符代替

public static void main(String[] args) {
System.out.println(str.length());
StringThread thread = new StringThread(str);
thread.start();

}

}

class StringThread extends Thread{
public StringThread(String str){
this.str = str;
}
private String str;
private Random random = new Random();
public void run(){
while(true){
String str1 = this.str.substring(random.nextInt(2056));
str1.intern();
try {
Thread.sleep(10);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}

jconsole显示结果图像为：

看到平行的曲线，我就表示不理解了，然后看jstat的结果：

0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 86.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0.00 0.00 88.44 0.00 15.22 0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000
0 0.000 0 0.000 0.000

Eden后面就长期稳定在一个数值了，这说明了2个问题：

JMX会影响到测试；
在重复new String()的情况下并没有真正的去创建对象。

感谢涛哥，@RednaxelaFX