Java那些坑(1):Java7的substring

问题描述

应用服务器从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

<code>&lt;</code><code>insert</code> <code>id</code><code>=</code><code>"insertBatchMap"</code> <code>parameterType</code><code>=</code><code>"Map"</code><code>&gt;</code>

<code>   </code><code>INSERT INTO BTT_LOG</code>

<code>    </code><code>(</code>

<code>        </code><code>ID,</code>

<code>        </code><code>DATATIME,</code>

<code>        </code><code>CHANNEL,</code>

<code>        </code><code>ORGAN_NO,</code>

<code>        </code><code>USER_ID,</code>

<code>    </code><code>)</code>

<code>    </code><code>VALUES</code>

<code>    </code><code>&lt;</code><code>foreach</code> <code>collection</code><code>=</code><code>"list"</code> <code>separator</code><code>=</code><code>","</code> <code>index</code><code>=</code><code>"i"</code> <code>item</code><code>=</code><code>"ls"</code><code>&gt;</code>

<code>    </code><code>(  </code>

<code>        </code><code>#{ls[ID],jdbcType=BIGINT},</code>

<code>    </code><code>#{ls[DATATIME],jdbcType=TIMESTAMP},</code>

<code>    </code><code>#{ls[CHANNEL],jdbcType=VARCHAR},</code>

<code>    </code><code>#{ls[ORGAN_NO],jdbcType=VARCHAR},</code>

<code>    </code><code>#{ls[USER_ID],jdbcType=VARCHAR},</code>

<code>    </code><code>&lt;/</code><code>foreach</code><code>&gt;</code>

<code>&lt;/</code><code>insert</code><code>&gt;</code>

传入一个Map，里面是个List。最终生成的sql是下面这样的：

<code>insert</code> 

<code>into</code> 

<code>BTT_LOG(ID,DATATIME,CHANNEL,ORGAN_NO,USER_ID) </code>

<code>values</code>

<code>(‘1’,’2016-07-22’,’0’,’000001’) </code>

<code>(‘2’,’2016-07-23’,’0’,’000002’)</code>

<code>......</code>

这个sql的作用是将当前库的数据迁移到历史库，一条sql迁移1000条，每天大约2000万的数据，速度一下子慢了25倍，数据都导不完了。

问题分析

看数据库中sql的执行时间，也就用了1s左右，因此肯定不是数据库的问题。通过VisualVM查看CPU热点，发现热点在org.apache.ibatis.parsing.GenericTokenParser.parse上面，自用时间特别长。

<a href="http://s5.51cto.com/wyfs02/M00/84/F0/wKioL1eYIcrzrth-AASbXFyQWEs588.png" target="_blank"></a>

这个函数自用时间很长，看了下代码如下：

21

22

23

24

25

26

27

28

29

30

31

32

33

34

35

36

<code>  </code><code>public</code> <code>String parse1(String text) {</code>

<code>    </code><code>StringBuilder builder = </code><code>new</code> <code>StringBuilder();</code>

<code>    </code><code>if</code> <code>(text != </code><code>null</code><code>) {</code>

<code>      </code><code>String after = text;</code>

<code>      </code><code>int</code> <code>start = after.indexOf(openToken);</code>

<code>      </code><code>int</code> <code>end = after.indexOf(closeToken);</code>

<code>      </code><code>while</code> <code>(start &gt; -</code><code>1</code><code>) {</code>

<code>        </code><code>if</code> <code>(end &gt; start) {</code>

<code>          </code><code>String before = after.substring(</code><code>0</code><code>, start);</code>

<code>          </code><code>String content = after.substring(start + openToken.length(), end);</code>

<code>          </code><code>String substitution;</code>

<code>          </code><code>// check if variable has to be skipped</code>

<code>          </code><code>if</code> <code>(start &gt; </code><code>0</code> <code>&amp;&amp; text.charAt(start - </code><code>1</code><code>) == </code><code>'\\'</code><code>) {</code>

<code>            </code><code>before = before.substring(</code><code>0</code><code>, before.length() - </code><code>1</code><code>);</code>

<code>            </code><code>substitution = </code><code>new</code> <code>StringBuilder(openToken).append(content).append(closeToken).toString();</code>

<code>          </code><code>} </code><code>else</code> <code>{</code>

<code>            </code><code>substitution = handler.handleToken(content);</code>

<code>          </code><code>}</code>

<code>          </code><code>builder.append(before);</code>

<code>          </code><code>builder.append(substitution);</code>

<code>          </code><code>after = after.substring(end + closeToken.length());</code>

<code>        </code><code>} </code><code>else</code> <code>if</code> <code>(end &gt; -</code><code>1</code><code>) {</code>

<code>          </code><code>String before = after.substring(</code><code>0</code><code>, end);</code>

<code>          </code><code>builder.append(closeToken);</code>

<code>        </code><code>} </code><code>else</code> <code>{</code>

<code>          </code><code>break</code><code>;</code>

<code>        </code><code>}</code>

<code>        </code><code>start = after.indexOf(openToken);</code>

<code>        </code><code>end = after.indexOf(closeToken);</code>

<code>      </code><code>}</code>

<code>      </code><code>builder.append(after);</code>

<code>    </code><code>}</code>

<code>    </code><code>return</code> <code>builder.toString();</code>

<code>  </code><code>}</code>

感觉自用时间不应该那么长，大部分都是调用其他函数的，所以我怀疑这个自用时间是有问题的，可能包含了substring的时间。

我写了下面的代码做实验：

<code>public</code> <code>static</code> <code>void</code> <code>test() {</code>

<code>    </code><code>while</code><code>(</code><code>true</code><code>){</code>

<code>        </code><code>for</code><code>(</code><code>int</code> <code>i = </code><code>0</code><code>; i &lt; </code><code>100000000</code><code>; i++) {</code>

<code>            </code><code>String xxxx = </code><code>"jfkfsdfjskfjsdkfjsakjdkfjdskfjslfjslkfjsdkfjsdlfjsd"</code><code>.substring(</code><code>2</code><code>);</code>

<code>}</code>

这段代码对应的CPU抽样如下：

<a href="http://s4.51cto.com/wyfs02/M01/84/F1/wKiom1eYI8STh80tAAEmZ3DvZ1Q181.png" target="_blank"></a>

自用时间特别长，substring的时间很短。

然后我改了一下，把while(true)改成for(int i=0;i&lt;100;i++)，结果substring的时间很长。

<code>    </code> 

<code>    </code><code>for</code><code>(</code><code>int</code> <code>j=</code><code>0</code><code>; j &lt; </code><code>100</code><code>; j++){</code>

<code>    </code><code>for</code><code>(</code><code>int</code> <code>i = </code><code>0</code><code>; i &lt; </code><code>100000000</code><code>; i++) {</code>

<code>        </code><code>String xxxx = </code><code>"jfkfsdfjskfjsdkfjsakjdkfjdskfjslfjslkfjsdkfjsdlfjsd"</code><code>.substring(</code><code>2</code><code>);</code>

对应的抽样如下：

<a href="http://s5.51cto.com/wyfs02/M00/84/F1/wKiom1eYJEzzpj_lAAEfiPWZ6fE156.png" target="_blank"></a>

试了好多次都这样。然后我看了下它们的字节码：

使用while(true)的

<a href="http://s1.51cto.com/wyfs02/M02/84/F1/wKioL1eYJNOD9MJaAADO8B5Nxpk574.png" target="_blank"></a>

使用for循环的

<a href="http://s1.51cto.com/wyfs02/M02/84/F1/wKioL1eYJMLi6jpTAAEkwFwRjwk259.png" target="_blank"></a>

没有什么大区别，使用for循环时由于还需要做加法，判断是否小于100，所以自用的指令应该更多。substring方法的字节码远远多于这几条字节码，所以我觉得上面两个函数的时间都耗在substring上了。

我们用的MyBatis版本是3.1.1，我对比了下3.2.0和3.1.1的代码，发现了如下问题：

原来的代码：

<code>String after = text;</code>

<code>before = after.substring(</code><code>0</code><code>,start);</code>

<code>builder.append(before);</code>

变成了下面这样：

<code>char</code><code>[] src = text.toCharArray();</code>

<code>builder.append(src, offset, start - </code><code>1</code><code>)</code>

把所有原来的substring方法全部替换成了使用char数组加上起止位置。所以说substring一定有问题，在新版的MyBatis里不用了。

为什么我们的应用这个问题会特别明显，因为每条sql 1000行，每行100个字符的话就是10万个字符，parse这个函数需要对这个10万字符的字符串做上万次substring，所以出问题了。升级了新版的MyBatis，这个问题解决了。

那么substring到底有啥问题呢？其实是substring在java7里面做了修改，在java6里面使用substring，和使用char数组加起止位置是一样的，但是在java7里就不一样了。

String类主要有三个成员：

<code>private</code> <code>final</code> <code>char</code> <code>value[];  </code>

<code>private</code> <code>final</code> <code>int</code> <code>offset;  </code>

<code>private</code> <code>final</code> <code>int</code> <code>count;</code>

在1.6里面，substring以及它调用的构造函数如下：

<code>// JDK6,共享 value数组提升速度  </code>

<code>String(</code><code>int</code> <code>offset, </code><code>int</code> <code>count, </code><code>char</code> <code>value[]) {  </code>

<code>    </code><code>this</code><code>.value = value;  </code>

<code>    </code><code>this</code><code>.offset = offset;  </code>

<code>    </code><code>this</code><code>.count = count;  </code>

<code>}  </code>

<code>  </code> 

<code>public</code> <code>String substring(</code><code>int</code> <code>beginIndex, </code><code>int</code> <code>endIndex) {  </code>

<code>    </code><code>// 如果范围和自己一模一样,则返回自身,否则用value字符数组构造一个新的对象  </code>

<code>    </code><code>return</code> <code>((beginIndex == </code><code>0</code><code>) &amp;&amp; (endIndex == count)) ? </code><code>this</code> <code>:  </code>

<code>        </code><code>new</code> <code>String(offset + beginIndex, endIndex - beginIndex, value);  </code>

使用substring产生的新对象，和原来的对象共用一个char[]数组。

<a href="http://s4.51cto.com/wyfs02/M00/84/F2/wKioL1eYQ1nBQ87jAACgocrux90742.jpg" target="_blank"></a>

这样能提高性能。但是有风险，就是内存浪费（有人称之为”内存泄漏“，但是我觉得不能算内存泄露，因为这段内存是可以回收的），怎么浪费的呢？

<code>String x = </code><code>"一个非常非常长的字符，可能是从网上抓取的一段文字"</code><code>;</code>

<code>String y = x.substring(a,b); </code><code>//比较短</code>

<code>x不用了，被回收</code>

<code>y的使用时间很长，短时间内不会被回收</code>

问题就来了，原来x会有一个很长的char[]数组，使用substring后这个数组被y引用了，所以回收x的时候这个数组不会被回收，因为被y引用着，但是y只会用其中很短的一部分，造成了内存的浪费。

在1.7中做了修改，构造函数变成下面这样，每次都把自己的数组拷贝一份出来。

<code>public</code> <code>String(</code><code>char</code> <code>value[], </code><code>int</code> <code>offset, </code><code>int</code> <code>count) {  </code>

<code>    </code><code>this</code><code>.offset = </code><code>0</code><code>;</code>

<code>    </code><code>this</code><code>.count = count; </code>

<code>    </code><code>this</code><code>.value = Arrays.copyOfRange(value, offset, offset+count);  </code>

<a href="http://s4.51cto.com/wyfs02/M02/84/F2/wKioL1eYRPyCbqFNAACYlMe_Rfk702.jpg" target="_blank"></a>

这样就不会有内存浪费的问题了。但是性能肯定不如共享char[]数组，不过也不会太差。

本文转自nxlhero 51CTO博客，原文链接：http://blog.51cto.com/nxlhero/1830578，如需转载请自行联系原作者