欢迎投稿

今日深度:

记一次找因Redis使用不当导致应用卡死Bug的过程,使用不当

记一次找因Redis使用不当导致应用卡死Bug的过程,使用不当


首先说下问题现象:内网sandbox环境API持续1周出现应用卡死,所有api无响应现象

刚开始当测试抱怨环境响应慢的时候 ,我们重启一下应用,应用恢复正常,于是没做处理。但是后来问题出现频率越来越频繁,越来越多的同事开始抱怨,于是感觉代码可能有问题,开始排查。

首先发现开发的本地ide没有发现问题,应用卡死时候永利ag手机版|首页,redis都正常,并且无特殊错误日志。开始怀疑是sandbox环境机器问题(测试环境本身就很脆!_!)

于是ssh上了服务器 执行以下命令

top

这时发现机器还算正常,于是打算看下jvm 堆栈信息

先看下问题应用比较耗资源的线程

执行 top -H -p 12798

找到前3个相对比较耗资源的线程

jstack 查看堆内存?

  1. jstack?12798?|grep?12799的16进制?31ff?

没看出什么问题,上下10行也看看,于是执行

看到一些线程都是处于lock状态。但没有出现业务相关的代码,忽略了。这时候没有什么头绪。思考一番。决定放弃这次卡死状态的机器

为了保护事故现场 先 dump了问题进程所有堆内存,然后debug模式重启测试环境应用,打算问题再显时直接远程debug问题机器

第二天问题再现,于是通知运维nginx转发拿掉这台问题应用,自己远程debug tomcat。

自己随意找了一个接口,断点在接口入口地方,悲剧开始,什么也没有发生!API等待服务响应,没进断点。这时候有点懵逼,冷静了一会,在入口之前的aop地方下了个断点,再debug一次,这次进了断点,f8 N次后发现在执行redis命令的时候卡主了。继续跟,最后在到jedis的一个地方发现问题:

  1. /**??
  2. ?*?Returns?a?Jedis?instance?to?be?used?as?a?Redis?connection.?The?instance?can?be?newly?created?or?retrieved?from?a??
  3. ?*?pool.??
  4. ?*???
  5. ?*?@return?Jedis?instance?ready?for?wrapping?into?a?{@link?RedisConnection}.??
  6. ?*/??
  7. protected?Jedis?fetchJedisConnector()?{??
  8. ???try?{??
  9. ??????if?(usePool?&&?pool?!=?null)?{??
  10. ?????????return?pool.getResource();??
  11. ??????}??
  12. ??????Jedis?jedis?=?new?Jedis(getShardInfo());??
  13. ??????//?force?initialization?(see?Jedis?issue?#82)??
  14. ??????jedis.connect();??
  15. ??????return?jedis;??
  16. ???}?catch?(Exception?ex)?{??
  17. ??????throw?new?RedisConnectionFailureException("Cannot?get?Jedis?connection",?ex);??
  18. ???}??
  19. }?

上面pool.getResource()后线程开始wait

  1. public?T?getResource()?{??
  2. ??try?{??
  3. ????return?internalPool.borrowObject();??
  4. ??}?catch?(Exception?e)?{??
  5. ????throw?new?JedisConnectionException("Could?not?get?a?resource?from?the?pool",?e);??
  6. ??}??
  7. }?

return internalPool.borrowObject(); 这个代码应该是一个租赁的代码,接着跟

  1. public?T?borrowObject(long?borrowMaxWaitMillis)?throws?Exception?{??
  2. ????this.assertOpen();??
  3. ????AbandonedConfig?ac?=?this.abandonedConfig;??
  4. ????if?(ac?!=?null?&&?ac.getRemoveAbandonedOnBorrow()?&&?this.getNumIdle()??this.getMaxTotal()?-?3)?{??
  5. ????????this.removeAbandoned(ac);??
  6. ????}??
  7. ????PooledObject?p?=?null;??
  8. ????boolean?blockWhenExhausted?=?this.getBlockWhenExhausted();??
  9. ????long?waitTime?=?0L;??
  10. ????while(p?==?null)?{??
  11. ????????boolean?create?=?false;??
  12. ????????if?(blockWhenExhausted)?{??
  13. ????????????p?=?(PooledObject)this.idleObjects.pollFirst();??
  14. ????????????if?(p?==?null)?{??
  15. ????????????????create?=?true;??
  16. ????????????????p?=?this.create();??
  17. ????????????}??
  18. ????????????if?(p?==?null)?{??
  19. ????????????????if?(borrowMaxWaitMillis?
  20. ????????????????????p?=?(PooledObject)this.idleObjects.takeFirst();??
  21. ????????????????}?else?{??
  22. ????????????????????waitTime?=?System.currentTimeMillis();??
  23. ????????????????????p?=?(PooledObject)this.idleObjects.pollFirst(borrowMaxWaitMillis,?TimeUnit.MILLISECONDS);??
  24. ????????????????????waitTime?=?System.currentTimeMillis()?-?waitTime;??
  25. ????????????????}??
  26. ????????????}??
  27. ????????????if?(p?==?null)?{??
  28. ????????????????throw?new?NoSuchElementException("Timeout?waiting?for?idle?object");??
  29. ????????????}?

其中有段代码

  1. if?(p?==?null)?{???
  2. ????if?(borrowMaxWaitMillis?
  3. ????????p?=?(PooledObject)this.idleObjects.takeFirst();???
  4. ????}?else?{???
  5. ????????waitTime?=?System.currentTimeMillis();???
  6. ????????p?=?(PooledObject)this.idleObjects.pollFirst(borrowMaxWaitMillis,?TimeUnit.MILLISECONDS);???
  7. ????????waitTime?=?System.currentTimeMillis()?-?waitTime;???
  8. ????}???
  9. }??

borrowMaxWaitMillis<0会一直执行,然后一直循环了 开始怀疑这个值没有配置

找到redis pool配置,发现确实没有配置MaxWaitMillis,配置后else代码也是一个Exception 并不能解决问题

继续F8

  1. public?E?takeFirst()?throws?InterruptedException?{??
  2. ????this.lock.lock();??
  3. ????Object?var2;??
  4. ????try?{??
  5. ????????Object?x;??
  6. ????????while((x?=?this.unlinkFirst())?==?null)?{??
  7. ????????????this.notEmpty.await();??
  8. ????????}??
  9. ????????var2?=?x;??
  10. ????}?finally?{??
  11. ????????this.lock.unlock();??
  12. ????}??
  13. ????return?var2;??
  14. }?

到这边 发现lock字眼,开始怀疑所有请求api都被阻塞了

于是再次ssh 服务器 安装 arthas ,(Arthas 是Alibaba开源的Java诊断工具)

执行thread命令

发现大量http-nio的线程waiting状态,http-nio-8083-exec-这个线程其实就是出来http请求的tomcat线程

随意找一个线程查看堆内存

  1. thread?-428?

这是能确认就是api一直转圈的问题,就是这个redis获取连接的代码导致的,

解读这段内存代码? 所有线程都在等 @53e5504e这个对象释放锁。于是jstack 全局搜了一把53e5504e ,没有找到这个对象所在线程。

自此。问题原因能确定是 redis连接获取的问题。但是什么原因造成获取不到连接的还不能确定

再次执行 arthas 的thread -b (thread -b, 找出当前阻塞其他线程的线程)

没有结果。这边和想的不一样,应该是能找到一个阻塞线程的,于是看了下这个命令的文档,发现有下面的一句话

好吧,我们刚好是后者。。。。

再次整理下思路。这次修改redis pool 配置,将获取连接超时时间设置为2s,然后等问题再次复现时观察应用最后正常时干过什么。

添加一下配置

  1. JedisConnectionFactory?jedisConnectionFactory?=?new?JedisConnectionFactory();??
  2. .......??
  3. JedisPoolConfig?config?=?new?JedisPoolConfig();??
  4. config.setMaxWaitMillis(2000);??
  5. .......??
  6. jedisConnectionFactory.afterPropertiesSet();?

重启服务,等待。。。。

又过一天,再次复现

ssh 服务器,检查tomcat accesslog ,发现大量api 请求出现500,

  1. org.springframework.data.redis.RedisConnectionFailureException:?Cannot?get?Jedis?connection;?nested?exception?is?redis.clients.jedis.exceptions.JedisConnectionException:?Could?not?get?a?resource?fr?
  2. ?om?the?pool??
  3. ????at?org.springframework.data.redis.connection.jedis.JedisConnectionFactory.fetchJedisConnector(JedisConnectionFactory.java:140)??
  4. ????at?org.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:229)??
  5. ????at?org.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:57)??
  6. ????at?org.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:128)??
  7. ????at?org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:91)??
  8. ????at?org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:78)??
  9. ????at?org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:177)??
  10. ????at?org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:152)??
  11. ????at?org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:85)??
  12. ????at?org.springframework.data.redis.core.DefaultHashOperations.get(DefaultHashOperations.java:48)?

找到源头第一次出现500地方,

发现以下代码..

  1. .....??
  2. Cursor?c?=?stringRedisTemplate.getConnectionFactory().getConnection().scan(options);??
  3. while?(c.hasNext())?{??
  4. .....,,??
  5. ???}?

分析这个代码,stringRedisTemplate.getConnectionFactory().getConnection()获取pool中的redisConnection后,并没有后续操作,也就是说此时redis 连接池中的链接被租赁后并没有释放或者退还到链接池中,虽然业务已处理完毕 redisConnection 已经空闲,但是pool中的redisConnection的状态还没有回到idle状态

正常应为

自此问题已经找到。

总结:spring stringRedisTemplate 对redis常规操作做了一些封装,但还不支持像 Scan SetNx等命令,这时需要拿到jedis Connection进行一些特殊的Commands

使用

  1. stringRedisTemplate.getConnectionFactory().getConnection()?

是不被推荐的

我们可以使用

  1. stringRedisTemplate.execute(new?RedisCallback()?{??
  2. ?????@Override??
  3. ?????public?Cursor?doInRedis(RedisConnection?connection)?throws?DataAccessException?{??
  4. ???????return?connection.scan(options);??
  5. ?????}??
  6. ???});?

来执行,

或者使用完connection后 ,用

  1. RedisConnectionUtils.releaseConnection(conn,?factory);?

来释放connection.

同时,redis中也不建议使用keys命令,redis pool的配置应该合理配上,否则出现问题无错误日志,无报错,定位相当困难。

www.htsjk.Com true http://www.htsjk.com/shujukukf/37393.html NewsArticle 记一次找因Redis使用不当导致应用卡死Bug的过程,使用不当 首先说下问题现象:内网sandbox环境API持续1周出现应用卡死,所有api无响应现象 刚开始当测试抱怨环境响应慢的时候 ,我们重...
评论暂时关闭