问题描述
应用服务器从Weblogic 10升级到了Weblogic 12，对应的jdk也从1.6升级到了1.7，结果原来的一个sql执行时间从1s变成了25s。
这个sql是使用Mybatis进行的动态拼装，如下，省略了一些字段。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
|
<
insert
id
=
"insertBatchMap"
parameterType
=
"Map"
>
INSERT INTO BTT_LOG
(
ID,
DATATIME,
CHANNEL,
ORGAN_NO,
USER_ID,
)
VALUES
<
foreach
collection
=
"list"
separator
=
","
index
=
"i"
item
=
"ls"
>
(
#{ls[ID],jdbcType=BIGINT},
#{ls[DATATIME],jdbcType=TIMESTAMP},
#{ls[CHANNEL],jdbcType=VARCHAR},
#{ls[ORGAN_NO],jdbcType=VARCHAR},
#{ls[USER_ID],jdbcType=VARCHAR},
)
</
foreach
>
</
insert
>
|
传入一个Map，里面是个List。最终生成的sql是下面这样的：
|
1
2
3
4
5
6
7
8
|
insert
into
BTT_LOG(ID,DATATIME,CHANNEL,ORGAN_NO,USER_ID)
values
(‘1’,’2016-07-22’,’0’,’000001’)
(‘2’,’2016-07-23’,’0’,’000002’)
......
......
|
这个sql的作用是将当前库的数据迁移到历史库，一条sql迁移1000条，每天大约2000万的数据，速度一下子慢了25倍，数据都导不完了。
问题分析
看数据库中sql的执行时间，也就用了1s左右，因此肯定不是数据库的问题。通过VisualVM查看CPU热点，发现热点在org.apache.ibatis.parsing.GenericTokenParser.parse上面，自用时间特别长。
这个函数自用时间很长，看了下代码如下：
|
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
|
public
String parse1(String text) {
StringBuilder builder =
new
StringBuilder();
if
(text !=
null
) {
String after = text;
int
start = after.indexOf(openToken);
int
end = after.indexOf(closeToken);
while
(start > -
1
) {
if
(end > start) {
String before = after.substring(
0
, start);
String content = after.substring(start + openToken.length(), end);
String substitution;
// check if variable has to be skipped
if
(start >
0
&& text.charAt(start -
1
) ==
'\\'
) {
before = before.substring(
0
, before.length() -
1
);
substitution =
new
StringBuilder(openToken).append(content).append(closeToken).toString();
}
else
{
substitution = handler.handleToken(content);
}
builder.append(before);
builder.append(substitution);
after = after.substring(end + closeToken.length());
}
else
if
(end > -
1
) {
String before = after.substring(
0
, end);
builder.append(before);
builder.append(closeToken);
after = after.substring(end + closeToken.length());
}
else
{
break
;
}
start = after.indexOf(openToken);
end = after.indexOf(closeToken);
}
builder.append(after);
}
return
builder.toString();
}
|
感觉自用时间不应该那么长，大部分都是调用其他函数的，所以我怀疑这个自用时间是有问题的，可能包含了substring的时间。
我写了下面的代码做实验：
|
1
2
3
4
5
6
7
|
public
static
void
test() {
while
(
true
){
for
(
int
i =
0
; i <
100000000
; i++) {
String xxxx =
"jfkfsdfjskfjsdkfjsakjdkfjdskfjslfjslkfjsdkfjsdlfjsd"
.substring(
2
);
}
}
}
|
这段代码对应的CPU抽样如下：
自用时间特别长，substring的时间很短。
然后我改了一下，把while(true)改成for(int i=0;i<100;i++)，结果substring的时间很长。
|
1
2
3
4
5
6
7
8
|
public
static
void
test() {
for
(
int
j=
0
; j <
100
; j++){
for
(
int
i =
0
; i <
100000000
; i++) {
String xxxx =
"jfkfsdfjskfjsdkfjsakjdkfjdskfjslfjslkfjsdkfjsdlfjsd"
.substring(
2
);
}
}
}
|
对应的抽样如下：
试了好多次都这样。然后我看了下它们的字节码：
使用while(true)的
使用for循环的
没有什么大区别，使用for循环时由于还需要做加法，判断是否小于100，所以自用的指令应该更多。substring方法的字节码远远多于这几条字节码，所以我觉得上面两个函数的时间都耗在substring上了。
我们用的MyBatis版本是3.1.1，我对比了下3.2.0和3.1.1的代码，发现了如下问题：
原来的代码：
|
1
2
3
|
String after = text;
before = after.substring(
0
,start);
builder.append(before);
|
变成了下面这样：
|
1
2
|
char
[] src = text.toCharArray();
builder.append(src, offset, start -
1
)
|
把所有原来的substring方法全部替换成了使用char数组加上起止位置。所以说substring一定有问题，在新版的MyBatis里不用了。
为什么我们的应用这个问题会特别明显，因为每条sql 1000行，每行100个字符的话就是10万个字符，parse这个函数需要对这个10万字符的字符串做上万次substring，所以出问题了。升级了新版的MyBatis，这个问题解决了。
那么substring到底有啥问题呢？其实是substring在java7里面做了修改，在java6里面使用substring，和使用char数组加起止位置是一样的，但是在java7里就不一样了。
String类主要有三个成员：
|
1
2
3
|
private
final
char
value[];
private
final
int
offset;
private
final
int
count;
|
在1.6里面，substring以及它调用的构造函数如下：
|
1
2
3
4
5
6
7
8
9
10
11
12
13
|
// JDK6,共享 value数组提升速度
String(
int
offset,
int
count,
char
value[]) {
this
.value = value;
this
.offset = offset;
this
.count = count;
}
public
String substring(
int
beginIndex,
int
endIndex) {
// 如果范围和自己一模一样,则返回自身,否则用value字符数组构造一个新的对象
return
((beginIndex ==
0
) && (endIndex == count)) ?
this
:
new
String(offset + beginIndex, endIndex - beginIndex, value);
}
|
使用substring产生的新对象，和原来的对象共用一个char[]数组。
这样能提高性能。但是有风险，就是内存浪费（有人称之为”内存泄漏“，但是我觉得不能算内存泄露，因为这段内存是可以回收的），怎么浪费的呢？
|
1
2
3
4
|
String x =
"一个非常非常长的字符，可能是从网上抓取的一段文字"
;
String y = x.substring(a,b);
//比较短
x不用了，被回收
y的使用时间很长，短时间内不会被回收
|
问题就来了，原来x会有一个很长的char[]数组，使用substring后这个数组被y引用了，所以回收x的时候这个数组不会被回收，因为被y引用着，但是y只会用其中很短的一部分，造成了内存的浪费。
在1.7中做了修改，构造函数变成下面这样，每次都把自己的数组拷贝一份出来。
|
1
2
3
4
5
|
public
String(
char
value[],
int
offset,
int
count) {
this
.offset =
0
;
this
.count = count;
this
.value = Arrays.copyOfRange(value, offset, offset+count);
}
|
这样就不会有内存浪费的问题了。但是性能肯定不如共享char[]数组，不过也不会太差。
本文转自nxlhero 51CTO博客，原文链接：http://blog.51cto.com/nxlhero/1830578，如需转载请自行联系原作者
