java序列化:ejb和java序列化(1)--发现并分析问题

　　这是加入新公司后接手第个项目使用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思路方法中:

　　 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 {
　　(queueEmpty) null;
　　synchronized (lock) {
　　　　 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例子有个和个String所以当invokeWriteObject思路方法被次时思路方法lookup/processQueue/poll/reallyPoll将被2000次同样等待锁加持锁和释放锁操作也要执行2000次虽然真正业务思路方法reallyPoll执行非常快

　　可以看到当线程增加时percentage1、percentage2变化已经可以介绍说明问题因此最后我给出我见解:

　　1. java序列化是cpu依赖型

　　2. synchronized lock严重影响java序列化

延伸阅读

• 2011-9-5-- 序列化,.NET简谈组件程序设计之(渗入序列化过程)
• 2011-9-11-- java序列化,Java序列化的高级认识
• 2010-11-24-- 序列化,解决编程中序列化问题
• 2010-11-24-- 反序列化,C#序列化与反序列化(Serializable and Deserialize)
• 2011-6-14-- 序列化和反序列化,我记录网站综合系统 -- 技术原理解析[5：JSON 序列化 反序列化]
• 2011-3-27-- 序列化,C#基础之序列化（2）
• 2011-5-12-- 对象序列化,序列化匿名对象
• 2010-11-29-- 数据序列化,数据序列化处理之经验积累（3） -- ObjectStateFormatter
• 2011-3-14-- mfc序列化,你所知道的MFC序列化
• 2011-4-17-- 序列化,ESFramework 4.0 快速上手（11） －－ 使用紧凑的序列化器，数倍提升性能