sun的程序员也是程序员啊！(续)

刚刚鄙视完sun，继续performance tuning，结果又发现问题：测试中，偶尔会出现一些古怪错误，经检查，发现有以下可疑的异常：

[# | 2010 - 05 - 05T14: 27 : 37.295 + 0800 | WARNING | sun - glassfish - comms - server2. 0 | com.sun.jbi.httpsoapbc.OutboundMessageProcessor | _ThreadID = 53 ;_ThreadName = HTTPBC - OutboundReceiver - 47 ;_RequestID = 42321e60 - 6723 - 4831 - a99a - b4dd1ac3e35f; | HTTPBC - E00759: An exception occured  while  processing a reply message. HTTP transport error: java.util.ConcurrentModificationException
com.sun.xml.ws.client.ClientTransportException: HTTP transport error: java.util.ConcurrentModificationException
        at com.sun.xml.ws.transport.http.client.HttpClientTransport.getOutput(HttpClientTransport.java: 134 )
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.process(HttpTransportPipe.java: 143 )
        at com.sun.xml.ws.transport.http.client.HttpTransportPipe.processRequest(HttpTransportPipe.java: 89 )
        at com.sun.xml.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java: 91 )
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java: 595 )
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java: 554 )
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java: 539 )
        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java: 436 )
        at com.sun.xml.ws.api.pipe.helper.AbstractTubeImpl.process(AbstractTubeImpl.java: 106 )
        at com.sun.xml.ws.tx.client.TxClientPipe.process(TxClientPipe.java: 177 )
        at com.sun.xml.ws.api.pipe.helper.PipeAdapter.processRequest(PipeAdapter.java: 115 )
        at com.sun.xml.ws.api.pipe.Fiber.__doRun(Fiber.java: 595 )
        at com.sun.xml.ws.api.pipe.Fiber._doRun(Fiber.java: 554 )
        at com.sun.xml.ws.api.pipe.Fiber.doRun(Fiber.java: 539 )
        at com.sun.xml.ws.api.pipe.Fiber.runSync(Fiber.java: 436 )
        at com.sun.xml.ws.client.Stub.process(Stub.java: 248 )
        at com.sun.xml.ws.client.dispatch.DispatchImpl.doInvoke(DispatchImpl.java: 180 )
        at com.sun.xml.ws.client.dispatch.DispatchImpl.invoke(DispatchImpl.java: 206 )
        at com.sun.jbi.httpsoapbc.OutboundMessageProcessor.outboundCall(OutboundMessageProcessor.java: 1256 )
        at com.sun.jbi.httpsoapbc.OutboundMessageProcessor.dispatch(OutboundMessageProcessor.java: 1296 )
        at com.sun.jbi.httpsoapbc.OutboundMessageProcessor.processRequestReplyOutbound(OutboundMessageProcessor.java: 747 )
        at com.sun.jbi.httpsoapbc.OutboundMessageProcessor.processMessage(OutboundMessageProcessor.java: 257 )
        at com.sun.jbi.httpsoapbc.OutboundAction.run(OutboundAction.java: 63 )
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java: 886 )
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java: 908 )
        at java.lang.Thread.run(Thread.java: 619 )
Caused by: java.util.ConcurrentModificationException
        at java.util.HashMap$HashIterator.nextEntry(HashMap.java: 793 )
        at java.util.HashMap$EntryIterator.next(HashMap.java: 834 )
        at java.util.HashMap$EntryIterator.next(HashMap.java: 832 )
        at com.sun.xml.ws.transport.http.client.HttpClientTransport.createHttpConnection(HttpClientTransport.java: 364 )
        at com.sun.xml.ws.transport.http.client.HttpClientTransport.getOutput(HttpClientTransport.java: 118 )
        ... 25  more

    从异常上看，调用metro进行webservice的调用过程中，有对hashmap做游历进行读取的操作，期间抛出ConcurrentModificationException。感觉这个又是bug了，毕竟这个前前后后的代码，都是sun自己的：openESB, metro, jdk。

    找到hashmap抛出异常的代码：

        final  Entry < K,V >  nextEntry() {
             if  (modCount  !=  expectedModCount)
                 throw   new  ConcurrentModificationException();

    明显这个ConcurrentModificationException是hashmap主动抛出的，看条件if (modCount != expectedModCount)

    找到expectedModCount，HashIterator构造时初始化为当时hashmap实例的modCount并保持不再修改，实际就是记下迭代开始时hashmap的状态：

        HashIterator() {
            expectedModCount  =  modCount;
            ...
        }

    再看modCount相关代码

    /**
     * The number of times this HashMap has been structurally modified
     * Structural modifications are those that change the number of mappings in
     * the HashMap or otherwise modify its internal structure (e.g.,
     * rehash).  This field is used to make iterators on Collection-views of
     * the HashMap fail-fast.  (See ConcurrentModificationException).
      */
     transient   volatile   int  modCount;

    从javadoc中可以得知modCount是用来记录hashmap实例的结构被修改的次数。同时明确指出这个域用来在做迭代时实现fail-fast。

    现在非常明确的可以知道问题的来源了：在hashmap实例的坐迭代的过程中，其他线程修改了这个hashmap，导致modCount 和 expectedModCount不符，因此直接抛出ConcurrentModificationException)来实现fail-fast。

    hashmap的这个做法没有问题，那么问题就是出在它的使用者上了：为什么在hashmap进行迭代的过程中，会修改这个hashmap？而且，明显的没有做同步保护，要知道hashmap是明确申明不是线程安全的。

    先找到这个hashmap被调用的代码，metro下的HttpTransportPipe，方便起见请打开以下URL使用fisheye工具查看代码：

http://fisheye5.cenqua.com/browse/jax-ws-sources/jaxws-ri/rt/src/com/sun/xml/ws/transport/http/client/HttpTransportPipe.java?r=1.14

    public  Packet process(Packet request) {
        HttpClientTransport con;
         try  {
             //  get transport headers from message
            Map < String, List < String >>  reqHeaders  =  (Map < String, List < String >> ) request.invocationProperties.get(MessageContext.HTTP_REQUEST_HEADERS);
             // assign empty map if its null
             if (reqHeaders  ==   null ){
                reqHeaders  =   new  HashMap < String, List < String >> ();
            }

        ......

         for  (Map.Entry < String, List < String >>  entry : reqHeaders.entrySet()) {
            httpConnection.addRequestProperty(entry.getKey(), entry.getValue().get( 0 ));
        }

    出现问题的reqHeaders是从request中获取到的，明显是这个方法之外还有其他线程在修改这个hashmap。
   
    简单修改一下代码：

    public  Packet process(Packet request) {
        HttpClientTransport con;
         try  {
             //  get transport headers from message
            Map < String, List < String >>  reqHeaders  =   new  HashMap < String, List < String >> ();
            Map < String, List < String >>  reqHeadersInRequest  =  (Map < String, List < String >> ) request.invocationProperties.get(MessageContext.HTTP_REQUEST_HEADERS);
             // assign empty map if its null
             if (reqHeadersInRequest  !=   null ){
                reqHeaders.putAll(reqHeadersInRequest);
            }

    不直接使用原有的hashmap实例了，既然其他线程会同时进行修改操作，那么这个实例就是很不安全的了。我们重新new了一个新的HashMap,然后将原有HashMap的数据用putAll方法设置进入。用编译后的class文件覆盖glassfish/lib/webservice-rt.jar中的同名文件，重新测试，跑了20分钟，上述的ConcurrentModificationException异常没有再出现。

    总结一下这个bug反映的问题，sun的开发人员在metro中是这样使用hashmap：
1. 将hashmap按照引用在各个实例间传递
2. 在不同地方有不同线程同时读写
3. 读写时不加锁，不做同步保护

    很无语，这种做法，不是自己找死吗？hashmap不是线程安全，使用hashmap时并按照引用传递时，要不保证只读，要不就保证同时只有一个线程进行读写，前两者都不能保证就必须自己加锁做同步保护。

    后来找到这个类的最新版本，发现在后面的版本中已经fix这个问题，有兴趣的话可以打开下面的URL看版本对比，sun官方的fix方式和我上面的完全一致，呵呵。

http: // fisheye5.cenqua.com/browse/jax-ws-sources/jaxws-ri/rt/src/com/sun/xml/ws/transport/http/client/HttpTransportPipe.java?r1=1.14&r2=1.15&u=3&k=kv

    还有一个关联的issue，https://jax-ws.dev.java.net/issues/show_bug.cgi?id=467，看了一下内容，和我们的场景完全不一样，看来修改这个地方纯属巧合。

    说点题外话，算是牢骚吧：

    有点怀疑metro是不是根本就没有做过性能测试，我们的测试场景，openESB下通过bepl调用4个我们称为common service的webservice，目前大概做到1200个tps，算下来common service的webservice的tps大概是1200*4 = 5K附近，上面的问题就非常明显，之前tps没有上去前没有这么严重。

    可以参考我之前的一个blog， http://www.blogjava.net/aoxj/archive/2010/04/29/319706.html，在解决这里提到的http long connection 和 TIME_AIT的问题之前，我们的tps比较低，cpu压不上去，当时好像这个问题不明显。后来搞定之后tps上来了才暴露出来。

    考虑上一个blog中 == 比较无效导致cache失效的bug，我对metro的代码质量真是很没有信心。按说这样的大型项目，release之前怎么也要做做压力测试，稳定性测试之类，很容易发现类似问题才是。我相信，不是每个用metro的地方，tps都只需要跑几十tps而已吧。我在我的普通开发机上做测试，大概只能跑到100个tps，没有发现出错。换到比较强劲的机器，tps上到1000后，上面的错误立即凸现。

评论

25 楼 skydream 2010-12-26  

repou 写道

当你看到ConcurrentModificationException异常的时候，就知道这个不是普通的HashMap而是ConcurrentHashMap。

这个是发生问题的地方，你可以去看看jdk的源码，HashMap.java:， line 793

Caused by: java.util.ConcurrentModificationException
        at java.util.HashMap$HashI**terator.nextEntry(HashMap.java: 793 )
        at java.util.HashMap$EntryIterator.next(HashMap.java: 834 )
        at java.util.HashMap$EntryIterator.next(HashMap.java: 832 )

metro的代码我也贴出来过，你也可以下载，或者用我贴出来的fisheye工具，链接在帖子里面。

if (reqHeaders  ==   null ){
                reqHeaders  =   new  HashMap < String, List < String >> ();
            }

这个帖子中sun用的是HashMap，出问题的也是HashMap。

24 楼 skydream 2010-12-26  

repou 写道

多学习，不要轻易怀疑国外厂家的代码。

当你看到ConcurrentModificationException异常的时候，就知道这个不是普通的HashMap而是ConcurrentHashMap。

ConcurrentHashMap的迭代器(Iterators,Enumerations)是单线程的，并且不会抛出ConcurrentModificationException的。

基于楼主在帖子中控诉Sun没有同步保护，可知楼主对多线程经验很少，我本想帮你找到出错原因，但发现场景中有Ws还有一个什么metro，所以，我只能提示楼主深入测试一下ConcurrentHashMap在什么情况下会抛出ConcurrentModificationException，然后从调用模块的架构上去找原因。

ConcurrentHashMap是个很好用的容器，唯一的不足是迭代不能反映最新的变化。

拜托在指责他人前，先认真看看帖子，先看看别人在说什么。

否则会闹笑话的

我贴出来的exception 和代码你都不看清楚，服了你了。

23 楼 repou 2010-12-26  

多学习，不要轻易怀疑国外厂家的代码。

当你看到ConcurrentModificationException异常的时候，就知道这个不是普通的HashMap而是ConcurrentHashMap。

ConcurrentHashMap的迭代器(Iterators,Enumerations)是单线程的，并且不会抛出ConcurrentModificationException的。

基于楼主在帖子中控诉Sun没有同步保护，可知楼主对多线程经验很少，我本想帮你找到出错原因，但发现场景中有Ws还有一个什么metro，所以，我只能提示楼主深入测试一下ConcurrentHashMap在什么情况下会抛出ConcurrentModificationException，然后从调用模块的架构上去找原因。

ConcurrentHashMap是个很好用的容器，唯一的不足是迭代不能反映最新的变化。

22 楼 zxflb 2010-07-09  

楼主真是强大 啊

21 楼 eddie404956 2010-05-11  

嗯，之前我也压测压出了问题，现在的U真是很快。
题外话，HashMap不加同步锁，但是也是有好处的。像ConcurrentHashMap就不能放
null进去，很不方便啊。。。所以用Collections.synchroniz..(HashMap)就很好用了，不过序列化的时候麻烦点。

20 楼 it2010 2010-05-11  

额，你真用心啊，测试部错哦！

19 楼 luffyke 2010-05-10  

很佩服楼主的钻研精神，从发现bug，到阅读源码找到bug。确确实实学习了一会，很多问题都是要看完源码之后才能解决的。

18 楼 myreligion 2010-05-07  

hashmap不同步的确容易出现这种异常，在guzz slowupdate service测试时我也碰到了。当负载上去的时候，不同步进行遍历就抛出ConcurrentModificationException，这是意料中的，当出现这个错误的时候本来设计是直接放弃准备下一次在更新；但很奇怪的是一旦出现一次ConcurrentModificationException，HashMap好像以后每次都会抛出ConcurrentModificationException，根本没法再用，可能也是一个bug，具体原因还没有研究。。。

17 楼 Joo 2010-05-07  

70码男之前也提到过同样的问题,这个貌似很容易被错用阿
http://www.iteye.com/topic/619130
顺便问问fail-fast的概念

16 楼 skydream 2010-05-07  

Ulysses 写道

yewen0125 写道

搂主， 是你自己不理解HashMap的实现原理， 不是bug， 当你跌代时， 同时试图删除或增加对象时，就会抛异常， 是故意这样做的， 避免跌代时有人修改。因为java为了考率到了效率问题。 因为ValueIterator和HashMap施共享了数组， 否则就的大量复制对象， 并且ValueIterator使它的内部类。所有List和Set都是这样的。

你好像没有看懂楼主的意思

呵呵，yewen0125兄弟应该是没有看懂我的意思。

我说有bug是指metro的代码，不是说hashmap。hashmap的处理方式没有问题，现在出现的问题在于metro的对hashmap的使用上：一边迭代一边修改结构。这种方式为hashmap所不容，因此hashmap直截了当的抛出ConcurrentModificationException来表示“抗议”。

15 楼 Ulysses 2010-05-07  

yewen0125 写道

搂主， 是你自己不理解HashMap的实现原理， 不是bug， 当你跌代时， 同时试图删除或增加对象时，就会抛异常， 是故意这样做的， 避免跌代时有人修改。因为java为了考率到了效率问题。 因为ValueIterator和HashMap施共享了数组， 否则就的大量复制对象， 并且ValueIterator使它的内部类。所有List和Set都是这样的。

你好像没有看懂楼主的意思

14 楼 yewen0125 2010-05-07  

搂主， 是你自己不理解HashMap的实现原理， 不是bug， 当你跌代时， 同时试图删除或增加对象时，就会抛异常， 是故意这样做的， 避免跌代时有人修改。因为java为了考率到了效率问题。 因为ValueIterator和HashMap施共享了数组， 否则就的大量复制对象， 并且ValueIterator使它的内部类。所有List和Set都是这样的。

13 楼 xiangdefei 2010-05-07  

打个记号一下，有空再看。

楼主前辈，晚辈我对你的敬仰犹如滔滔江水，连绵不绝，又如黄河泛滥，一发不可收拾。

12 楼 Durian 2010-05-07  

skydream 写道

骨之灵魂 写道

牛  虽然看得不是很懂

估计你没有太认真看帖 ，呵呵，其实内容挺简单的，总结起来就一句话：

不要在对hashmap做迭代的同时，修改hashmap的结构。

-------------
C#如果做如上操作时要抛出异常的。

11 楼 skydream 2010-05-06  

骨之灵魂 写道

牛  虽然看得不是很懂

估计你没有太认真看帖 ，呵呵，其实内容挺简单的，总结起来就一句话：

不要在对hashmap做迭代的同时，修改hashmap的结构。

10 楼 skydream 2010-05-06  

hotjava 写道

请教一下，多线程的压力测试工具用的啥？ 是loadrunner么？

目前用的是soapui，功能测试和压力测试都是用这个。

对于压力测试而言，soapui稍嫌不够专业，按说用LoadRunner会更合适，不过我们目前并不要求得到很准确详尽的测试记录，能达到一定压力即可，焦点还是在发现和解决存在的问题，争取做到尽可能高的性能。

等我们的工作完成之后，会交给测试部分做专门的压力测试和稳定性测试。

9 楼 yujiang 2010-05-06  

cassandra里也有同样的问题, 这个东西其实挺常见的.

8 楼 骨之灵魂 2010-05-06  

牛  虽然看得不是很懂

7 楼 当里个当 2010-05-06  

压力测试是自己写多线程么

6 楼 hotjava 2010-05-06  

请教一下，多线程的压力测试工具用的啥？ 是loadrunner么？