新手区 一则性能测试问题分析案例

大话性能 · November 12, 2018 · Last by 大话性能 replied at November 12, 2018 · Last modified by admin 卡斯 · 1178 hits

在Java应用的性能测试中,很多性能问题可以通过观察线程堆栈来发现,Jstack是JVM自带dump线程堆栈的工具,很轻量易用,并且执行时不会对性能造成很大的影响。灵活的使用jstack可以发现很多隐秘的性能问题,是定位问题不可多得的好帮手。

1线程堆栈

线程堆栈也称作线程调用堆栈。Java线程堆栈是虚拟机中线程(包括锁)状态的一个瞬间快照,即系统在某个时刻所有线程的运行状态,包括每一个线程的调用堆栈,锁的持有情况等信息,从线程堆栈中可以得到以下信息:

线程的名字,ID,线程的数量等;

线程的运行状态,锁的状态(锁被那个线程持有,哪个线程在等待锁等);

函数间的调用关系,包括完整类名,所执行的方法,源代码的行数等;

2问题现象

在测试一个场景时,发现响应时间很长,日志也无报错现象,根据调用链逐级定位,发现80%的时间都是消耗在DAO层的方法上,这时首先考虑的是sql会不会有问题?于是找DBA同学帮忙抓sql看下,但DBA同学反映sql执行很快,执行计划也没有问题,那问题出现在哪里呢,找不到原因就看下线程堆栈,系统在dao层方法后做了什么?

此时就jstack就派上用场了。

jstack使用,一般来说执行jstack -l pid > test.txt,然后查看test.txt文件即可观察对比线程堆栈。

jstack线程堆栈如下:


"DubboServerHandler-10.165.184.51:20881-thread-200" daemon prio=10 tid=0x00007f2fd6208800 nid=0x504b waiting on condition [0x00007f2fc0280000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000078172f2c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at com.alibaba.druid.pool.DruidDataSource.pollLast(DruidDataSource.java:1487)
at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1086)
at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:953)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4544)
at com.alibaba.druid.filter.logging.LogFilter.dataSource_getConnection(LogFilter.java:827)
at com.alibaba.druid.filter.FilterChainImpl.dataSource_connect(FilterChainImpl.java:4540)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:931)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:923)
at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:100)
at org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(DataSourceUtils.java:111)
at org.springframework.jdbc.datasource.DataSourceUtils.getConnection(DataSourceUtils.java:77)
at org.mybatis.spring.transaction.SpringManagedTransaction.openConnection(SpringManagedTransaction.java:81)
at org.mybatis.spring.transaction.SpringManagedTransaction.getConnection(SpringManagedTransaction.java:67)
at org.apache.ibatis.executor.BaseExecutor.getConnection(BaseExecutor.java:279)
at org.apache.ibatis.executor.SimpleExecutor.prepareStatement(SimpleExecutor.java:72)
at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:59)
...

3问题分析

先关注线程状态,发现堆栈信息里大量的dubbo线程处于TIMED_WAITING状态,从“waiting on condition”可以看出系统在等待一个条件发生,这时的线程处于sleep状态,一般会有超时时间唤醒,一般出现TIMED_WAITING很正常,一些等待IO都会出现这种状态,但是大量的TIMED_WAITING就要找原因了,观察线程堆栈发现处于TIMED_WAITING状态的线程都在等待druid获取连接池的连接,这种现象很像连接池不够用了,于是增加数据库连接池的连接数,TPS直接提升了3倍。

4最后小结

在遇到一些系统挂起无响应,系统CPU较高,系统运行的响应时间长,线程死锁等现象的时候,可以利用jstack多执行对比几次线程堆栈情况,看看到底哪里出问题。

共收到 1 条回复 时间 点赞

经验分享

需要 Sign In 后方可回复, 如果你还没有账号请点击这里 Sign Up