n(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();
}
}
ejb与java序列化(1) 发现并分析问题(2)
时间:2011-01-22 blogjava Sky
可以看到通过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序列化 |