http://blog.csdn.net/fjpqzm/article/details/24261773
1. 环境信息
机器
CPU(个)
内存
系统
DBA(数据库服务器A)
16(64 core)
256G
AIX 6100-08(AL770_048)
DBB(数据库服务器B)
16(64 core)
256G
AIX 6100-08(AL770_048)
APPA(应用服务器A)
16(64 core)
256G
AIX 6100-08(AL770_048)
APPB(应用服务器B)
16(64 core)
256G
AIX 6100-08(AL770_048)
APPC(应用服务器C)
16(64 core)
256G
AIX 6100-08(AL770_048)
本次测试使用3台Load Runner客户机100并发压测，启动3台应用服务器(APPA，APPB，APPC)，每台服务器启动1个JVM进程，2台数据库服务器搭建Oracle RAC环境，只仅启动单节点。
数据流向如下：
3台LR客户机(100并发)
-> Tuxedo(100通道，消除Tuxedo排队因素)
-> Java应用(3台机器，每台个1个)
-> 数据库服务器(单节点)
2. 第一步：数据定位
现象：
在Load Runner对单交易做不同并发压力测试(目的：验证单交易并发情况下响应时间是否正常)时，发现单JVM并发越高时，响应时间越来越高，上升趋势非常明显，个别交易还出现CPU也很高的现象。
例如其中一个交易的TPS结果。
并发数(3台机器3个JVM)
TPS
响应时间(ms)
CPU(%)
20
430
25
14.4
40
651
32
25
100
146
349
72
从LR压测结果分析，100并发时响应时间很长，TPS却比40并发时还低，对本交易基本可排除数据库的因素，猜测Java应用存在锁竞争的现象。
3. 第二步：tprof分析
通过tprof命令分析java进程cpu瓶颈。
# 用root用户登录，采集60秒的数据
tprof -s -k -x sleep 60
采集的数据如下：
Process Freq Total Kernel User Shared Other
======= ==== ===== ====== ==== ====== =====
/usr/java5/jre/bin/java 177 52.77 5.69 0.00 44.83 2.24
可以看出java进程cpu主要消耗在“User Shared”(即jvm相关动态链接库)上面，继续分析究竟是哪些动态库消耗较多呢？
Shared Object %
============= ======
/lib/libpthread.a[shr_xpg5_64.o] 28.37
/usr/java6_64/jre/lib/ppc64/default/libj9jit24.so 10.33
/usr/java6_64/jre/lib/ppc64/default/libj9thr24.so 4.82
/usr/java6_64/jre/lib/ppc64/default/libj9gc24.so 0.66
/usr/java6_64/jre/lib/ppc64/default/libj9vm24.so 0.48
从此处可以确定pthread线程库占用时间很大，猜测问题与高并发使用多线程API引起的。
继续分析libpthread.a库中方法的cpu消耗情况。
Profile: /lib/libpthread.a[shr_xpg5_64.o]
Total % For All Processes (/lib/libpthread.a[shr_xpg5_64.o]) = 28.37
Subroutine % Source
========== ====== ======
.pthread_mutex_trylock 25.11 pthreads/pth_mutex.c
._global_trylock 1.79 reads/pth_spinlock.c
.global_unlock_ppc_mp 0.82 pth_locks_ppc_mp.s
._global_lock_common 0.32 reads/pth_spinlock.c
._local_trylock 0.12 reads/pth_spinlock.c
大量调用“pthread_mutex_trylock”(试图获取互斥锁)，基本上可以确定交易在并发高的情况下同步阻塞的情况很严重，下面再通过jvisualvm进一步验证下是不是存在大量阻塞的情况。
4. 第三步：jvisualvm分析
jvisualvm监控线程运行情况，分析是否有锁的存在？
通过截取LR压测时间段内的线程时序图，可看出线程处于“监视”的时间很长，现在基本可断定问题应该在于Java代码中大量线程存在资源竞争，可能是阻塞等待持有同一个锁或同步块等竞争资源。那究竟是什么代码引起的问题呢，进一步分析不同时点的javacore文件对比可得出结果。
5. 第四步：javacore分析
通过jvisualvm工具“线程dump”功能可以产生javacore文件，或者在服务端通过“kill -3 pid”也可以生成javacore文件。
分析javacore文件，查看锁的情况。
NULL ------------------------------------------------------------------------
0SECTION LOCKS subcomponent dump routine
NULL ===============================
NULL
1LKPOOLINFO Monitor pool info:
2LKPOOLTOTAL Current total number of monitors: 1150
NULL
1LKMONPOOLDUMP Monitor Pool Dump (flat & inflated object-monitors):
2LKMONINUSE sys_mon_t:0x00000100178A8618 infl_mon_t: 0x00000100178A8658:
3LKMONOBJECT sun/misc/GC$LatencyLock@0x07000000060065A0/0x07000000060065B8:
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "GC Daemon" (0x00000100196E7900)
2LKMONINUSE sys_mon_t:0x00000100171969A8 infl_mon_t: 0x00000100171969E8:
3LKMONOBJECT java/lang/ref/ReferenceQueue@0x07000000043C99B8/0x07000000043C99D0:
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "RMI RenewClean-[192.168.101.49:65116]" (0x0000010019821000)
2LKMONINUSE sys_mon_t:0x0000010019273AD8 infl_mon_t: 0x0000010019273B18:
3LKMONOBJECT java/lang/ref/ReferenceQueue@0x07000000001C89F0/0x07000000001C8A08:
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "RMI Reaper" (0x00000100196D8100)
2LKMONINUSE sys_mon_t:0x0000010019273FA0 infl_mon_t: 0x0000010019273FE0:
3LKMONOBJECT [I@0x07000000043C9A40/0x07000000043C9A58:
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "JMX server connection timeout 95" (0x0000010019BE7D00)
2LKMONINUSE sys_mon_t:0x0000010019274798 infl_mon_t: 0x00000100192747D8:
3LKMONOBJECT com/sun/jmx/remote/internal/ArrayNotificationBuffer@0x0700000006037000/0x0700000006037018:
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "RMI TCP Connection(4)-192.168.101.49" (0x0000010015F56700)
2LKMONINUSE sys_mon_t:0x000001001CDC9750 infl_mon_t: 0x000001001CDC9790:
3LKMONOBJECT java/util/Collections$SynchronizedMap@0x07000000001C8F58/0x07000000001C8F70: owner "Pool-2-(BizServer)-thread-105" (0x000001001EA36200), entry count 1
3LKWAITERQ Waiting to enter:
3LKWAITER "Pool-2-(BizServer)-thread-25" (0x000001001D3A2700)
3LKWAITER "Pool-2-(BizServer)-thread-27" (0x000001001B61E900)
3LKWAITER "Pool-2-(BizServer)-thread-28" (0x00000100198AF300)
3LKWAITER "Pool-2-(BizServer)-thread-29" (0x0000010019767700)
3LKWAITER "Pool-2-(BizServer)-thread-30" (0x000001001A652300)
3LKWAITER "Pool-2-(BizServer)-thread-31" (0x000001001A589B00)
3LKWAITER "Pool-2-(BizServer)-thread-108" (0x000001001C37E900)
3LKWAITER "Pool-2-(BizServer)-thread-109" (0x000001001D7E5000)
3LKWAITER "Pool-2-(BizServer)-thread-110" (0x0000010015F41E00)
3LKWAITER "Pool-2-(BizServer)-thread-111" (0x000001001A4CC600)
3LKWAITER "Pool-2-(BizServer)-thread-113" (0x000001001B9E4E00)
3LKWAITER "Pool-2-(BizServer)-thread-114" (0x000001001BB98500)
3LKWAITER "Pool-2-(BizServer)-thread-116" (0x000001001EA0D300)
3LKWAITER "Pool-2-(BizServer)-thread-118" (0x000001001D692600)
3LKWAITER "Pool-2-(BizServer)-thread-119" (0x000001001C25B300)
3LKWAITER "Pool-2-(BizServer)-thread-120" (0x000001001D352E00)
3LKWAITER "Pool-2-(BizServer)-thread-121" (0x000001001C7E2A00)
3LKWAITER "Pool-2-(BizServer)-thread-122" (0x000001001C75A800)
3LKWAITER "Pool-2-(BizServer)-thread-123" (0x000001001A6D9F00)
3LKWAITER "Pool-2-(BizServer)-thread-127" (0x000001001CE55F00)
3LKWAITER "Pool-2-(BizServer)-thread-128" (0x000001001CEA8400)
3LKWAITER "Pool-2-(BizServer)-thread-130" (0x000001001C3D5600)
3LKWAITER "Pool-2-(BizServer)-thread-131" (0x000001001D78A500)
2LKMONINUSE sys_mon_t:0x000001001D3584E0 infl_mon_t: 0x000001001D358520:
3LKMONOBJECT java/util/Hashtable@0x0700000000C44020/0x0700000000C44038: owner "Pool-2-(BizServer)-thread-124" (0x00000100195A4200), entry count 1
2LKMONINUSE sys_mon_t:0x000001001B51D1C0 infl_mon_t: 0x000001001B51D200:
3LKMONOBJECT java/lang/ClassLoader$CacheTable@0x0700000006C03AF8/0x0700000006C03B10: Flat locked by "Pool-2-(BizServer)-thread-103" (0x000001001EA2A800), entry count 1
2LKMONINUSE sys_mon_t:0x000001001C72F740 infl_mon_t: 0x000001001C72F780:
3LKMONOBJECT [I@0x07000000085B0428/0x07000000085B0440:
3LKNOTIFYQ Waiting to be notified:
3LKWAITNOTIFY "JMX server connection timeout 294" (0x000001001C75D900)
NULL
该时点有23个线程“Pool-2-(BizServer)-thread-xxx”阻塞等待线程“Pool-2-(BizServer)-thread-105”释放锁，继续分析线程“Pool-2-(BizServer)-thread -105”当前调用堆栈。
3XMTHREADINFO "Pool-2-(BizServer)-thread-105" J9VMThread:0x000001001EA36200, j9thread_t:0x000001001AFF2BC0,
java/lang/Thread:0x07000000003C4F18, state:CW, prio=5
3XMJAVALTHREAD (java/lang/Thread getId:0x10A, isDaemon:false)
3XMTHREADINFO1 (native thread ID:0x1EF0215, native priority:0x5, native policy:UNKNOWN)
3XMTHREADINFO3 Java callstack:
4XESTACKTRACE at java/util/Collections$SynchronizedMap.containsKey(Collections.java:726(Compiled Code))
4XESTACKTRACE at java/lang/reflect/Proxy.isProxyClass(Proxy.java:752(Compiled Code))
4XESTACKTRACE at cn/xxx/util/PropertyUtil.createAccessor(PropertyUtil.java:141(Compiled Code))
在PropertyUtil.createAccessor方法里头调用Proxy.isProxyClass方法，该方法最终调用SynchronizedMap. containsKey()方法，分析SynchronizedMap的代码可以看出该类中大量方法都使用“synchronized”语义。
public boolean containsKey(Object key) {
synchronized(mutex){return m.containsKey(key);}
}
到了这里，可以确定在高并发情况下Proxy.isProxyClass方法方法会大量阻塞在“synchronized”同步块上，那解决办法也就是在这方面上做文章，对目前的应用来说此处可以不调用该方法，去除它。
6. 总结
6.1 单交易不同并发测试的案例，可以用于验证高并发时是否有Java锁的存在。
LoadRunner压测时，建议挑选大部分交易进行该类案例的测试。
6.2 压测结果分析过程中，多种方式有时可以得出一样的结论，相互验证结论更可靠。
如：本次分析过程中，通过tprof+jvisualvm+javacore多种方式的分析最终都指向同样的结果。
6.3 再小的同步块“synchronized”都有可能是问题所在，所以慎重对待它。
对交易系统而言，最好能增加“synchronized”关键字使用的代码评审。
另外，不要过于相信第三方jar包的可靠性，使用方式不对或使用场景的变化都有可能导致第三方jar包呈现出不同的效率问题。
扫一扫
2097
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
