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: <unowned> 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: <unowned> 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: <unowned> 3LKNOTIFYQ Waiting to be notified: 3LKWAITNOTIFY "RMI Reaper" (0x00000100196D8100) 2LKMONINUSE sys_mon_t:0x0000010019273FA0 infl_mon_t: 0x0000010019273FE0: 3LKMONOBJECT [I@0x07000000043C9A40/0x07000000043C9A58: <unowned> 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: <unowned> 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: <unowned> 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包呈现出不同的效率问题。
