前言:这是几个月前压测某项目登录接口时遇到的性能问题,虽然大家不一定会遇到,但是分析定位问题的思路还是可以参考一下。
1、压测过程中,tps突然剧烈下降,且所有请求失败(下图绿线)
服务端错误日志,获取不到redis连接池(Could not get a resource from the pool),另外,从下图可以看到,当前jedis版本是2.9.1
获取不到连接,可能是这四种情况:
Timeout waiting for idle object
Pool exhausted
Unable to activate object
Unable to validate object
下图,表示等待空闲连接超时
2、jedis的连接池就是用commons-pool2来管理的,使用jvisualvm打开对应的应用进程,根据上图的提示,找到org.apache.commons.pool2
可以看到相关的配置
活动连接1000,连接满了
dump堆内存进行分析(此时压测已经停止)
根据文章开头的日志信息,搜索org.apache.commons.pool2.impl,然后双击下面的DefaultPooledObject类
进入实例
实例状态是ALLOCATED
ALLOCATED表示在使用中,压测结束后,虽然连接释放了,但是资源没归还
下面可以看到,dataSource为空
如果dataSource为空,就走else,说明只关闭了连接,资源没归还到队列中,后面的线程就获取不到空闲连接
可以看到,实例有很多
为什么会出现这种情况呢?
通过查看源码及官网,可以确定,这是2.9.1的bug,改为2.9.0就没报错了。
官网:https://github.com/xetorthio/jedis/pull/1918/commits/df1bffa3c77f4ede4c912f2c3e78b5c8857725e7
Move dataSource reset before connection returned to pool.
If datasource reset after the connection returned to pool, it might reset the datasource after it was allocated to another thread
意思是:在连接返回到池之前重置移动数据源。
如果数据源在连接返回到池之后重置,那么它可能会在将数据源分配给另一个线程之后重置该数据源
3、出现很多实例状态是ALLOCATED,dataSource为null的原因:
在多线程时,如果dataSource在连接释放后重置(根据代码逻辑可知:连接释放前,资源已经归还,但是未重置),可能在重置前,这个dataSource已经分配给另外一个线程了,此时重置,就把已经获取了这个dataSource的线程的dataSource重置了,这样就导致很多状态是ALLOCATED、dataSource值为null的实例,进而这些线程都只关闭了连接,而没有归还资源,最终导致获取不到连接,即文章开头的异常日志信息,这也印证了都是压测一段时间后才开始报错的现象。
另外,有些性能问题,还是需要一定的代码能力,而且,测试会代码是个趋势。