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

大话性能 · 2018年11月12日 · 最后由 大话性能 回复于 2018年11月12日 · 1763 次阅读

在 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 条回复 时间 点赞

经验分享

需要 登录 后方可回复, 如果你还没有账号请点击这里 注册