刚刚鄙视完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后，上面的错误立即凸现。