這是加入新公司后接手的第一個項目，使用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序列化