这是加入新公司后接手的第一个项目，使用weblogic9.2 + ejb2.0，压力测试时发现速度非常慢，响应时间很不理想，检查日志发现，某些ejb相互调用时方法调用的时间非常长，高达300-500毫秒。非常夸张，因为两个日志之间只是间隔了一个ejb调用。通过thread dump分析后发现有相当多的线程在wait，检查线程调用绽发现是在将参数进行序列化时，线程试图加锁但是锁被占用，因此处于等待状态。考虑到thread dump的这一瞬间，有多达30-50个线程都在同时试图在同一个锁上加锁，很明显这里的锁竞争非常严重。
因此强烈怀疑是java的序列化机制导致的问题，由于weblogic/ejb之类的太复杂不方便测试，因此单独写了一个类来模拟这种场景:
1. 有大量线程在运行，期间都有序列化的操作
2. 被序列化的对象比较大，有大量子对象（子对象的子对象...)
运行测试代码，问题重现，测试用开了50个线程，thread dump并分析thread dump信息，发现49个线程处于waiting 状态，只有一个线程在干活！因此抛开weblogic/ejb单独分析java的序列化机制，首先看thread dump的线程信息：
占有锁的线程:
"testthread21" prio=6 tid=0x0ad2d3b8 nid=0x224 runnable [0x0b48f000..0x0b48fce4]
at java.io.ObjectStreamClass.processQueue(Unknown Source)
at java.io.ObjectStreamClass.lookup(Unknown Source)
at java.io.ObjectOutputStream.writeObject0(Unknown Source)
at java.io.ObjectOutputStream.writeObject(Unknown Source)
at java.util.ArrayList.writeObject(Unknown Source)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at java.io.ObjectStreamClass.invokeWriteObject(Unknown Source)
at java.io.ObjectOutputStream.writeSerialData(Unknown Source)
at java.io.ObjectOutputStream.writeOrdinaryObject(Unknown Source)
at java.io.ObjectOutputStream.writeObject0(Unknown Source)
at java.io.ObjectOutputStream.writeObject(Unknown Source)
at test.Test.test(Test.java:68)
at test.Test.run(Test.java:53)
at java.lang.Thread.run(Unknown Source)
等待加锁的线程之一:
"testthread49" prio=6 tid=0x0ad9a508 nid=0xa9c waiting for monitor entry [0x0bb8f000..0x0bb8fbe4]
at java.lang.ref.ReferenceQueue.poll(Unknown Source)
- waiting to lock <0x02fb1d40> (a java.lang.ref.ReferenceQueue$Lock)
at java.io.ObjectStreamClass.processQueue(Unknown Source)
at java.io.ObjectStreamClass.lookup(Unknown Source)
at java.io.ObjectOutputStream.writeObject0(Unknown Source)
at java.io.ObjectOutputStream.writeObject(Unknown Source)
at java.util.ArrayList.writeObject(Unknown Source)
at sun.reflect.GeneratedMethodAccessor1.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
at java.lang.reflect.Method.invoke(Unknown Source)
at java.io.ObjectStreamClass.invokeWriteObject(Unknown Source)
at java.io.ObjectOutputStream.writeSerialData(Unknown Source)
at java.io.ObjectOutputStream.writeOrdinaryObject(Unknown Source)
at java.io.ObjectOutputStream.writeObject0(Unknown Source)
at java.io.ObjectOutputStream.writeObject(Unknown Source)
at test.Test.test(Test.java:68)
at test.Test.run(Test.java:53)
at java.lang.Thread.run(Unknown Source)
可以发现问题发生在类java.io.ObjectStreamClass中的方法processQueue()方法中：
static void processQueue(ReferenceQueue<Class<?>> queue,
ConcurrentMap<? extends
WeakReference<Class<?>>, ?> map)
{
Reference<? extends Class<?>> ref;
while((ref = queue.poll()) != null) {
map.remove(ref);
}
}
这里的queue.poll()有加锁，继续跟进poll()的代码：
public Reference<? extends T> poll() {
if(queueEmpty) return null;
synchronized (lock) {
return reallyPoll();
}
}
可以看到通过synchronized 关键字，在lock对象有加锁操作，和thread dump信息相符，看来问题就在这里了。
开始分析了，首先看现象，“50个线程1个进入synchronized 块获得锁，49个在试图加锁而处于waiting状态”，首先想到的是，synchronized块中的代码执行的时间比较长，造成锁长时间处于被占有状态，其他线程只能等。但是查看reallyPoll()方法发现它的实现非常简单，执行应该非常快，后面的profile信息也证实了这点。
profile统计信息：
method num calls cumulative time mothod time percentage1 percentage2
thread=1
invokeWriteObject 387 30209 2
lookup 774778 17499 6605 57.9%
processQueue 774778 5523 2185
poll 774786 3338 2294 7.59%
reallyPoll 774793 1045 1045
thread=2
invokeWriteObject 739 59715 3
lookup 1479482 34550 12815 57.85%
processQueue 1479482 11878 4236
poll 1479490 7642 5656 9.47%
reallyPoll 1479497 1987 1987
thread=5
invokeWriteObject 721 147203 3
lookup 1443446 99665 24631 67.7%
processQueue 1443446 58211 7044
poll 1443454 51167 49196 51.33%
reallyPoll 1443461 1971 1971
thread=50
invokeWriteObject 701 1438319 3
lookup 1403406 1369971 228508 95.24%
processQueue 1403406 1125351 6801
poll 1403414 1118550 1116462 77.62%
reallyPoll 1403421 2089 2089
注释：
num calls = number of methed calls
percentage1=lookup cumulative time / invokeWriteObject cumulative time
percentage2=poll mothod time / invokeWriteObject cumulative time
注意：当我们序列化一个Data对象的实例时，因为这个实例里面带有一个包含1000个DataItem实例的ArrayList，而每个DataItem实例有一个int和一个String。所以当invokeWriteObject方法被调用一次时，方法lookup/processQueue/poll/reallyPoll将被调用2000次。同样等待锁，加持锁和释放锁的操作也要执行2000次，虽然真正的业务方法reallyPoll执行的非常快。
可以看到当线程增加时，percentage1、percentage2的变化已经可以说明问题。因此，最后我给出我的见解：
1. java序列化是cpu依赖型
2. synchronized lock严重影响java序列化