這是加入新公司后接手的第一個項目，使用weblogic9.2 + ejb2.0，壓力測試時發(fā)現(xiàn)速度非常慢，響應(yīng)時間很不理想，檢查日志發(fā)現(xiàn)，某些ejb相互調(diào)用時方法調(diào)用的時間非常長，高達(dá)300-500毫秒。非常夸張，因為兩個日志之間只是間隔了一個ejb調(diào)用。通過thread dump分析后發(fā)現(xiàn)有相當(dāng)多的線程在wait，檢查線程調(diào)用綻發(fā)現(xiàn)是在將參數(shù)進(jìn)行序列化時，線程試圖加鎖但是鎖被占用，因此處于等待狀態(tài)。考慮到thread dump的這一瞬間，有多達(dá)30-50個線程都在同時試圖在同一個鎖上加鎖，很明顯這里的鎖競爭非常嚴(yán)重。
因此強烈懷疑是java的序列化機制導(dǎo)致的問題，由于weblogic/ejb之類的太復(fù)雜不方便測試，因此單獨寫了一個類來模擬這種場景:
1. 有大量線程在運行，期間都有序列化的操作
2. 被序列化的對象比較大，有大量子對象（子對象的子對象...)
運行測試代碼，問題重現(xiàn)，測試用開了50個線程，thread dump并分析thread dump信息，發(fā)現(xiàn)49個線程處于waiting 狀態(tài)，只有一個線程在干活！因此拋開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)
可以發(fā)現(xiàn)問題發(fā)生在類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()有加鎖，繼續(xù)跟進(jìn)poll()的代碼：
public Reference<? extends T> poll() {
if(queueEmpty) return null;
synchronized (lock) {
return reallyPoll();
}
}
可以看到通過synchronized 關(guān)鍵字，在lock對象有加鎖操作，和thread dump信息相符，看來問題就在這里了。
開始分析了，首先看現(xiàn)象，“50個線程1個進(jìn)入synchronized 塊獲得鎖，49個在試圖加鎖而處于waiting狀態(tài)”，首先想到的是，synchronized塊中的代碼執(zhí)行的時間比較長，造成鎖長時間處于被占有狀態(tài)，其他線程只能等。但是查看reallyPoll()方法發(fā)現(xiàn)它的實現(xiàn)非常簡單，執(zhí)行應(yīng)該非常快，后面的profile信息也證實了這點。
profile統(tǒng)計信息：
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
注意：當(dāng)我們序列化一個Data對象的實例時，因為這個實例里面帶有一個包含1000個DataItem實例的ArrayList，而每個DataItem實例有一個int和一個String。所以當(dāng)invokeWriteObject方法被調(diào)用一次時，方法lookup/processQueue/poll/reallyPoll將被調(diào)用2000次。同樣等待鎖，加持鎖和釋放鎖的操作也要執(zhí)行2000次，雖然真正的業(yè)務(wù)方法reallyPoll執(zhí)行的非常快。
可以看到當(dāng)線程增加時，percentage1、percentage2的變化已經(jīng)可以說明問題。因此，最后我給出我的見解：
1. java序列化是cpu依賴型
2. synchronized lock嚴(yán)重影響java序列化