sun的程序员也是程序员啊！

    依然是近期工作中发现的问题，真实案例，写下来分享给大家。

    在开始本文之前，援引同事对此案例的一句评语：sun的程序员也是程序员啊！

    开始讲故事吧，依然是performance tuning，还是老伎俩，加压力，做thread dump，然后检查。结果就发现有如下的线程，而且比率极大：dump出来大概总共70-80个工作线程，有5-6个在做这个事情，还有大概50个在等着做这个事情，也就是说大概80%+的工作线程都于此有关。

" HTTPBC-OutboundReceiver-221 "  daemon prio = 3  tid = 0x09872c00  nid = 0x4bf9  runnable [ 0xa7b56000 ]
   java.lang.Thread.State: RUNNABLE
    at java.util.zip.ZipFile.getEntry(Native Method)
    at java.util.zip.ZipFile.getEntry(ZipFile.java: 149 )
     -  locked  < 0xbb09d458 >  (a java.util.jar.JarFile)
    at java.util.jar.JarFile.getEntry(JarFile.java: 206 )
    at java.util.jar.JarFile.getJarEntry(JarFile.java: 189 )
    at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java: 754 )
    at sun.misc.URLClassPath$JarLoader.findResource(URLClassPath.java: 732 )
    at sun.misc.URLClassPath$ 1 .next(URLClassPath.java: 195 )
    at sun.misc.URLClassPath$ 1 .hasMoreElements(URLClassPath.java: 205 )
    at java.net.URLClassLoader$ 3 $ 1 .run(URLClassLoader.java: 393 )
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader$ 3 .next(URLClassLoader.java: 390 )
    at java.net.URLClassLoader$ 3 .hasMoreElements(URLClassLoader.java: 415 )
    at sun.misc.CompoundEnumeration.next(CompoundEnumeration.java: 27 )
    at sun.misc.CompoundEnumeration.hasMoreElements(CompoundEnumeration.java: 36 )
    at sun.misc.CompoundEnumeration.next(CompoundEnumeration.java: 27 )
    at sun.misc.CompoundEnumeration.hasMoreElements(CompoundEnumeration.java: 36 )
    at sun.misc.CompoundEnumeration.next(CompoundEnumeration.java: 27 )
    at sun.misc.CompoundEnumeration.hasMoreElements(CompoundEnumeration.java: 36 )
    at sun.misc.CompoundEnumeration.next(CompoundEnumeration.java: 27 )
    at sun.misc.CompoundEnumeration.hasMoreElements(CompoundEnumeration.java: 36 )
    at sun.misc.CompoundEnumeration.next(CompoundEnumeration.java: 27 )
    at sun.misc.CompoundEnumeration.hasMoreElements(CompoundEnumeration.java: 36 )
    at com.sun.xml.ws.util.ServiceFinder$LazyIterator.hasNext(ServiceFinder.java: 357 )
    at com.sun.xml.ws.api.pipe.TransportTubeFactory.create(TransportTubeFactory.java: 129 )
    at com.sun.xml.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java: 112 )
    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 )
     -  locked  < 0xe8e3e200 >  (a com.sun.xml.ws.api.pipe.Fiber)
    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 )
     -  locked  < 0xe8e3e200 >  (a com.sun.xml.ws.api.pipe.Fiber)
    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 )

    忘了介绍一下背景：openESB运行于 glassfish平台，一个bepl 调用4个webservice.上面的线程HTTPBC-OutboundReceiver 是openESB中作为客户端调用webservice的工作线程，从调用栈中可以看到:
1. task被executor执行
2. jbi中的httpsoapbc用来处理消息
3. com.sun.xml.ws.client使用Stub来处理信息，标准的webservice调用
4. 最重要的两行，我们后面再来看这里发生了什么
    at com.sun.xml.ws.api.pipe.TransportTubeFactory.create(TransportTubeFactory.java:129)
    at com.sun.xml.ws.transport.DeferredTransportPipe.processRequest(DeferredTransportPipe.java:112)
5. ServiceFinder，通过Iterator.hasNext在做游历
6. java的classloader在find resource
7. 为了从jar包中装载resouce，需要处理解压缩，java.util.zip被调用

    OK，现在整体看，在处理webservice的调用过程中，需要在classpath路径下载入资源，而且看样子这个资源的载入还是很耗cpu时间的。

    先看看在装载什么资源，上面的调用明显是jax-ws，glassfish下跑的是metro的实现。在glassfish目录下找到webservice-rt.jar，打开看META-INF/MANIFEST.MF,找到Name: jaxws-rt.jar这段，发现有Implementation-Version: 2.1.3.1，上metro的官网，找metor 相应版本的源文件，最接近的是2.1.3。下载下来查看源码，恩，开源就是好啊。

    首先找到ServiceFinder类，代码片段：

com.sun.xml.ws.util.ServiceFinder$LazyIterator.hasNext(ServiceFinder.java: 357 )
private   static    final  String  prefix  =   " META-INF/services/ " ;
  if  (configs   ==   null ) {
                    String fullName  =  prefix  +  service.getName();
                     if  (loader  ==   null )
                        configs  =  ClassLoader.getSystemResources(fullName);
                     else
                        configs  =  loader.getResources(fullName);
}

    非常通用的做法，META-INF/services/下查找资源看改用哪个实现。

    逆推找到类TransportTubeFactory中对此的调用代码：

    public   static  Tube create(@Nullable ClassLoader classLoader, @NotNull ClientTubeAssemblerContext context) {
         for  (TransportTubeFactory factory : ServiceFinder.find(TransportTubeFactory. class ,classLoader)) {
            Tube tube  =  factory.doCreate(context);
             if (tube  != null ) {
                TransportTubeFactory.logger.fine(factory.getClass() + "  successfully created  " + tube);
                 return  tube;
            }
        }

    代码的意图很明显，create()方法在classpath下找到TransportTubeFactory的实现，然后逐个尝试创建Tube对象。

    疑问就来了，为什么每次请求都要create, 这里的create明显是重量级的，需要到classpath下去查找一下某个Factory的实现。明显不合理，继续逆推代码，在类DeferredTransportPipe中找到对create的调用：

    public  NextAction processRequest(@NotNull Packet request) {
         if (request.endpointAddress == address)
             //  cache hit
             return  transport.processRequest(request);
    .....
        address  =  request.endpointAddress;
        transport  =  TransportTubeFactory.create(classLoader, newContext);

    不出意料的，这里有cache: 如果endpoint address和上次相同，直接重用，否则就调用create方法。从前面的现象看，cache没有命中，至少没有全部命中。

    由于我们的测试的案例是连续调用4个不同的webservice，当然每个webservice的endpoint address是不同的。因此第一反应是这里transport cache机制被四个webservice的client端公用，因此每次调用只有1/4的概率和上次相同，其他的3/4就只能重新创建。之后花费了大量时间和精力去查看openesb的代码，过程不提，结果就是无果。

    再回头来看这个cache的地方，有点奇怪为什么不命中。好在可以做remote debug，debug进入，到if(request.endpointAddress==address ) 这行，发现果然没有命中，但是随即检查request.endpointAddress和 address的值，非常惊讶的发现里面的实际值是相同的！！

    直接晕倒！

if (request.endpointAddress == address )

    值相同而==不成立，那么就是说这里的request.endpointAddress 和 address 并不是一般的enum或者类型安全枚举， ==的检测根本不成立。

    这是sun的代码啊，sun的程序员也会犯这种低级错误？用 == 来比较普通对象而不是用equals()方法？

    继续看EndpointAddress 这个类，无语了：

1. 这是个普通的类，根本不是enum或者类型安全枚举，有两个publish的构造函数，理论上，使用者可以随意创建任意数量的实例
2. 没有重载equals方法，因此即使改用equals方法来提到==的检查也是无意义的，默认的equals()还是检查对象引用

    因此，再来看DeferredTransportPipe中的这段试图重用cache的代码

    public  NextAction processRequest(@NotNull Packet request) {
         if (request.endpointAddress == address)
             //  cache hit
             return  transport.processRequest(request);

    这里的"if(request.endpointAddress==address)"能否成立，完全取决于客户端的调用方法：如果调用方保证每次相同endpointAddress的请求，request.endpointAddress都会是同一个实例，则这里的cache可以命中。否则这个cache毫无意义，还是需要每次重新创建重量级的transport对象。我们的测试案例中，很明显，openESB的程序员，没有考虑到DeferredTransportPipe这里的"特殊"要求，每次调用传入的request.endpointAddress虽然里面的实际值相同，但是每次都是不同的实例。因此 == 不成立，cache不命中。

    查找了一下相关的类和接口定义，对于方法public NextAction processRequest(Packet request) 和 Packet中的endpointAddress属性，没有任何javadoc说明要求Packet中的endpointAddress属性需要做到相同地址只使用一个对象实例。

    看Packet中的endpointAddress的设值代码：

   public   void  setEndPointAddressString(String s) {
         if (s == null )
             this .endpointAddress  =   null ;
         else
             this .endpointAddress  =  EndpointAddress.create(s);
    }
     public   static  EndpointAddress create(String url) {
         try  {
             return   new  EndpointAddress(url);
        }  catch (URISyntaxException e) {
             throw   new  WebServiceException( " Illegal endpoint address:  " + url,e);
        }
    }

    明显每次通过调用setEndPointAddressString()设置时都会产生一个新的EndpointAddress实例。看代码时还意外的发现，

    public  EndpointAddress endpointAddress;

    这个endpointAddress属性居然是public的！！ 看样子，DeferredTransportPipe类的开发者，是寄希望于调用者不要通过Packet.setEndPointAddressString(String s)来设置，而是希望直接使用public的属性，这样才有希望命中cache！这分明是在挖坑，而且明显现在openESB的开发者被坑进去了！

    鄙视啊鄙视，这样的代码，居然是sun的程序员写出来的，还放在metro里面，而metro作为默认的jax-ws实现被放在jdk中...... 很是无语。

    无奈之下，修改代码，将 == 去掉，自己简单的判断一下endpointAddress的实际值

        if  (address  !=   null
                 &&  address.getURI()  !=   null
                 &&  request.endpointAddress.getURI().equals(address.getURI())) {
             //  cache hit
             return  transport.processRequest(request);
        }

    将编译出来的class文件，替换glassfish/lib/webservice-rt.jar中的相同文件，重新测试。再次thread dump，发现问题解决了。

    期间看了一下DeferredTransportPipe类的各个version的代码，这里的 == 一直都没有改，难道sun就一直没有发现这里有问题？有兴趣的可以通过下面的地址使用fisheye来查看这个类的代码：

http://fisheye5.cenqua.com/browse/jax-ws-sources/jaxws-ri/rt/src/com/sun/xml/ws/transport/DeferredTransportPipe.java?r1=1.3&r2=1.3.4.1&u=-1


    总结：用 == 来比较非enum或者类型安全枚举的对象实例，这种错误一般只有初学者才犯，万万没有想到，在metro这样级别的代码中也能出现。无限感叹啊，再次援引同事的评语作为本文的结束语：

    sun的程序员也是程序员啊！

 

后续更新：

1. 下午做了这个bug解决前后的性能对比，相同机器相同环境

 

fix前： CPU: 89%-92%   TPS:1111   AVG response time:71

fix后： CPU: 69%-71%   TPS:1300   AVG response time:61  

 

总结说就是fix之后，tps 提升接近20%，而cpu使用反而降低20%，平均响应时间减少14%。

反过来，看原来的这个bug对性能的影响有多大，如此差异仅仅源于一行代码而已。

 

2. 提交给sun的tr，24小时了，没有任何反应

    好吧，不能指望sun了。

评论

25 楼 ninja9turtle 2010-07-09  

skydream 写道

很无奈的顶起这个帖子，因为提交给sun的bug，两个月过去了，依然没有任何回应。

https://jax-ws.dev.java.net/issues/show_bug.cgi?id=854

这个可怕的bug依然还在metro中存在，全世界使用metro的人，都得不到fix。我有找到问题的能力，有解决问题的方法，有提交bug的精神，奈何sun就是选择无视......

公司原本有和sun合作的官方渠道，奈何后来因故不能使用，我也无法以公司的名义来提交bug/提醒sun。javaeye上的朋友，如果有哪位有途径，看看能否帮忙提交这个bug到sun，或者提醒他们早日修改。

另外由于metro的不良表现，推荐大家在选择jax-ws的实现时，尽量选择诸如cxf之类的社区比较活跃的版本吧。sun，感觉已经不能指望了。

Oracle管理下的JDK、现在的Spring、现在的JBoss都得走向商业化才能持之以恒的发展，我们公司用apple的cocoa，还有adobe的flash，特别是早期的flex1、2甚至现在的flex3、4都不知道遇到了提交多少bug，很多情况下只能无奈采取其他方式的绕开，更不用说sun这些opensource的项目，遇到问题只能找其他办法绕开，要苦等他们修复有可能好多年都没动静

24 楼 skydream 2010-07-09  

很无奈的顶起这个帖子，因为提交给sun的bug，两个月过去了，依然没有任何回应。

https://jax-ws.dev.java.net/issues/show_bug.cgi?id=854

这个可怕的bug依然还在metro中存在，全世界使用metro的人，都得不到fix。我有找到问题的能力，有解决问题的方法，有提交bug的精神，奈何sun就是选择无视......

公司原本有和sun合作的官方渠道，奈何后来因故不能使用，我也无法以公司的名义来提交bug/提醒sun。javaeye上的朋友，如果有哪位有途径，看看能否帮忙提交这个bug到sun，或者提醒他们早日修改。

另外由于metro的不良表现，推荐大家在选择jax-ws的实现时，尽量选择诸如cxf之类的社区比较活跃的版本吧。sun，感觉已经不能指望了。

23 楼 JustDoNow 2010-05-12  

佩服楼主的钻研精神
当程序员需要当楼主这样的

22 楼 skydream 2010-05-07  

后续更新：

1. 下午做了这个bug解决前后的性能对比，相同机器相同环境

fix前： CPU: 89%-92%   TPS:1111   AVG response time:71
fix后： CPU: 69%-71%   TPS:1300   AVG response time:61 

总结说就是fix之后，tps 提升接近20%，而cpu使用反而降低20%，平均响应时间减少14%。

反过来，看原来的这个bug对性能的影响有多大，如此差异仅仅源于一行代码而已。

2. 提交给sun的tr，24小时了，没有任何反应

    好吧，不能指望sun了。

21 楼 berlou 2010-05-06  

Sun在某些项目上测试力度根本不够，相反一些商业软件公司这方面做的很好。
Sun有些产品甚至不怎么测试就会release， 错误多也难免。

20 楼 berlou 2010-05-06  

哪的程序员都是程序员， Sun, IBM, Microsoft, 甚至如日中天的Google， 都一样。
没有不犯错的程序员的。
楼主精神可嘉，值得学习。

19 楼 Element&lina 2010-05-06  

前段时间看了下Cassandra的代码，也很乱。。。。错误谁都可以犯，其实这并不可怕，怕的是你都不知道犯了错

18 楼 everlasting_188 2010-05-06  

不错，学些了。

17 楼 skydream 2010-05-06  

顺便推荐一个前几天发的文章，同是这次调优中发现的问题，glassfish下使用http 长连接中出现的问题和解决方法。对于使用glassfish的同学应该会有所帮助。

glassfish下的性能调优：令人极度困惑的Max Connections参数
http://www.iteye.com/topic/656368

和这两个文章有点类似，不过性质好一些，只是sun/glassfish下的属性命名和注解，文档等不一致造成理解困难。sun的命名方式太随意了一点。

16 楼 skydream 2010-05-06  

刚刚在java.net上注册了个账号，提交了这个bug

https://jax-ws.dev.java.net/issues/show_bug.cgi?id=854

English不怎么地，大家将就点。

现在等sun来确认和fix，不过我们自己肯定等不及，还是需要自己fix然后自己更新glassfish，这种做法以后维护很是头疼，安装部署更是费力，比较惨。

15 楼 qx8668 2010-05-06  

太牛了！！

14 楼 skydream 2010-05-06  

有兴趣的朋友可以顺便看看我的另外一个帖子

http://www.iteye.com/topic/659885

昨天下午发现并解决的问题，和这个很类似，也是metro的代码有问题，在使用hashmap时不当造成高并发下出现错误。不同的是这个bug在后来的新版本中被sun自己fix了。本来也想提交bug的，结果一查最新版本已经fix了。

13 楼 skydream 2010-05-06  

题外话，说说对sun的看法，或者说感情吧。

作为一个java程序员，而且是基本靠java吃饭的程序员，对于sun的感情，不言而喻。敬重，景仰，痛惜，哀其不幸，怒其不争......

sun的不幸，是大家的不幸。

以我们的产品为例，原来运行于weblogic，我们用了一年的时间做准备 + 一个团队大半年的开发时间为代码才勉强移植到glassfish，这个月就要release了。可是现在看看glassfish的前景，真是郁闷啊。

我手头正在调优的这个项目，openESB + glassfish + netbeans，还没有做完开发和测试，就已经开始要考虑替换为其他的esb实现了，因为openESB和netbeans的roadmap让我们不敢再在上面投资。

sun被收购，对我们的影响是很大的。

12 楼 skydream 2010-05-06  

xyz20003 写道

佩服楼主的钻研精神，感谢楼主的奉献精神。

也希望楼主在感叹sun程序员考虑不周的时候，在有余力的情况下，将此类bug及时报告给官方，让官方可以尽快修改这个bug。

越多的参与开发社区，越能左右影响项目的发展。不只是bug，任何好的想法，强力的feature都可以直接扔给开发社区，我觉得这是开源社区与公司实现共同利益的好方法。如果只在国内社区抱怨，对整个开源项目的影响太有限了。毕竟国内的commiter太少。很难及时反馈到官方。

其实像楼主这么能钻，只要有精力，去官方搞一个contributor下来也没问题，到时候有什么问题都在trunk下直接改了。方便啊。

这个问题是这几天才发现的，昨天上午才刚刚发现bug出现在 == 上，中午hack后测试通过才整理出来。
今天我们会联系sun，准备提交这个问题。

11 楼 bonny 2010-05-06  

额，佩服楼主。

像我最多追到官方包就停了，基本不会怀疑sun的质量。不过IBM的质量我敢怀疑的，曾经追一个字符集转换的bug追到IBM JDK的官方包（是java.****，而不是com.***）。相当的鄙视IBM的代码质量。


不过，像这样的软件，基本上是靠设计和靠架构 ，整体上，设计还是非常不错滴。

10 楼 skydream 2010-05-06  

fengsky491 写道

kimmking 写道

1、对lz的钻研精神表示pf
2、有一个疑问，这个地方到底是bug，还是design

另外，我直接就看不懂楼主的代码，还要学习

呵呵，不是我的代码了，上面贴出来的代码都是sun的。

帖子有点长，因为需要分析整个过程，如果你不关注细节，可以直接看这一行：

   public  NextAction processRequest(@NotNull Packet request) {
         if (request.endpointAddress == address)
             //  cache hit
             return  transport.processRequest(request);

问题的实质就是这个地方用 == 来比较两个实例，而这两个实例没有任何保证他们会是同一个对象的。

9 楼 xyz20003 2010-05-06  

佩服楼主的钻研精神，感谢楼主的奉献精神。

也希望楼主在感叹sun程序员考虑不周的时候，在有余力的情况下，将此类bug及时报告给官方，让官方可以尽快修改这个bug。

越多的参与开发社区，越能左右影响项目的发展。不只是bug，任何好的想法，强力的feature都可以直接扔给开发社区，我觉得这是开源社区与公司实现共同利益的好方法。如果只在国内社区抱怨，对整个开源项目的影响太有限了。毕竟国内的commiter太少。很难及时反馈到官方。

其实像楼主这么能钻，只要有精力，去官方搞一个contributor下来也没问题，到时候有什么问题都在trunk下直接改了。方便啊。

8 楼 evaspring 2010-05-06  

凡是软件都难免会有BUG ~

7 楼 20055294 2010-05-06  

还是 要敬重 下Sun 的人

6 楼 fengsky491 2010-05-06  

kimmking 写道

1、对lz的钻研精神表示pf
2、有一个疑问，这个地方到底是bug，还是design

另外，我直接就看不懂楼主的代码，还要学习