当前位置: 首页 > 科技观察

还记得找Redis使用不当导致应用卡bug的过程吗

时间:2023-03-21 00:56:28 科技观察

首先说一下问题现象:内网沙箱环境API卡了1周,所有API都没有反应。一开始,当测试抱怨环境响应慢的时候,我们重启了应用,应用又恢复正常了,所以我们没有处理。但是后来,出问题的频率越来越频繁,越来越多的同事开始抱怨,于是觉得代码可能有问题,开始排查。首先我发现开发的本地ide没发现什么问题。应用卡住的时候,数据库和redis都是正常的,也没有特别的错误日志。开始怀疑是沙盒环境机器的问题(测试环境本身就很脆弱!_!),于是在服务器上sshd,执行如下命令top,发现机器还是正常的,于是我打算先查看jvm堆栈信息,看看问题所在。应用程序消耗更多资源。线程执行top-H-p12798找到前三个比较耗资源的线程jstack查看堆内存jstack12798|grep1279916进制31ff没看出什么问题,也看看上下10行,所以执行看看有的线程都处于锁定状态。但是没有业务相关的代码,忽略。这时,我毫无头绪。想想看。为了保护事故现场,我决定放弃卡机先把问题进程的堆内存全部dump掉,然后在debug模式下重启测试环境应用。本来打算等问题重现直接远程调试问题机器,第二天问题又重现,于是通知运维Nginx转发下架这个有问题的应用,自己远程调试tomcat。随便找了一个接口,断点就在接口的入口处。悲剧开始了,什么都没有发生!API等待服务响应,不进入断点。这个时候有点迷茫,先冷静一下,在入口前的aop处下断点,重新调试。这次我进入了断点。f8N次后,发现主卡在执行redis命令时卡住了。继续跟踪,终于在jedis的一个地方发现了问题:(usePool&&poolredisConnection){try{if(usePool&&poolredisConnection})getResource();}Jedisjedis=newJedis(getShardInfo());//强制初始化(seeJedisissue#82)jedis.connect();returnjedis;}catch(Exceptionex){thrownewRedisConnectionFailureException("CannotgetJedisconnection",ex);}}在池之上。在getResource()之后,线程启动这段代码应该是租赁代码,后面是publicTborrowObject(longborrowMaxWaitMillis)throwsException{this.assertOpen();AbandonedConfigac=this.abandonedConfig;if(ac!=null&&ac.getRemoveAbandonedOnBorrow()&&this.getNumIdle()<2&&this.getNumActive()>this.getMaxTotal()-3){this.removeAbandoned(ac);}PooledObjectp=null;booleanblockWhenExhausted=this.getBlockWhenExhausted();longwaitTime=0L;while(p==null){booleancreate=false;if(blockWhenExhausted){p=(PooledObject)this.idleObjects.pollFirst();if(p==null){create=true;p=this.create();}if(p==null){如果(borrowMaxWaitMillis<0L){p=(PooledObject)this.idleObjects.takeFirst();}else{waitTime=System.currentTimeMillis();p=(PooledObject)this.idleObjects.pollFirst(borrowMaxWaitMillis,TimeUnit.MILLISECONDS);waitTime=System.currentTimeMillis()-waitTime;}}if(p==null){thrownewNoSuchElementException("Timeoutwaitingforidleobject");}其中有段代码if(p==null){if(borrowMaxWaitMillis<0L){p=(PooledObject)this.idleObjects.takeFirst();}else{waitTime=System.currentTimeMillis();p=(PooledObject)this.idleObjects.pollFirst(borrowMaxWaitMillis,TimeUnit.MILLISECONDS);waitTime=System.currentTimeMillis()-waitTime;}}borrowMaxWaitMillis<0会一直执行,然后一直循环了开始我怀疑这个值没有配置。查找redispool配置,发现没有配置MaxWaitMillis。配置后else代码也是Exception,无法解决问题。继续F8publicEtakeFirst()throwsInterruptedException{this.lock.lock();Objectvar2;try{Objectx;while((x=this.unlinkFirst())==null){this.notEmpty.await();}var2=x;}finally{this.lock.unlock();}returnvar2;}发现这里有lock这个词,开始怀疑AllrequestAPIswereblocked,于是又在ssh服务器上安装了arthas,(Arthas是一个开源的Java诊断工具来自阿里巴巴)并执行thread命令发现大量http-nio线程等待状态,http-nio-8083-exec-这个线程居然出来了http请求的tomcat线程随机找了一个线程查看堆内存线程-428,可以确认是api一直在转圈圈的问题,是redis获取连接的代码导致的。解释这段内存代码,所有线程都在等待对象@53e5504e释放锁,jstack全局搜索了53e5504e,没有找到这个对象所在的线程。自那以后。问题原因可以确定是redis连接获取的问题。但不确定是什么原因导致连接失败。再次执行arthas的thread-b(thread-b,找出当前阻塞其他线程的线程)没有结果。这和我想的不一样。应该可以找到阻塞的线程,于是看了下这个命令的文档,发现了下面这句话。好吧,我们恰好是后者。...再次整理思路。这次修改redis池配置,设置连接超时为2s,然后观察问题再次出现时应用做了什么。添加配置JedisConnectionFactoryjedisConnectionFactory=newJedisConnectionFactory();......JedisPoolConfigconfig=newJedisPoolConfig();config.setMaxWaitMillis(2000);......jedisConnectionFactory.afterPropertiesSet();重新启动服务并等待。...又过一天,再次恢复ssh服务器,检查tomcat访问日志,发现大量api请求出现500,org.springframework.data.redis.RedisConnectionFailureException:CannotgetJedisconnection;nestedexceptionisredis.clients.jedis.exceptions.datafromdatafrom.CedisConnectiongException.CedisConnection.connection.jedis.JedisConnectionFactory.fetchJedisConnector(JedisConnectionFactory.java:140)atorg.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:229)atorg.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:57)atorg.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:128)atorg.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:91)atorg.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:78)atorg.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:177)atorg.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:152)atorg.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:85)attorg.springframework.data.redis.core.DefaultHashOperations.get(DefaultHashOperations.java:48)找到了第一次出现500的来源,找到了如下代码....Cursorc=stringRedisTemplate.getConnectionFactory().getConnection().扫描(选项);while(c.hasNext()){.....,,}分析这段代码,stringRedisTemplate.getConnectionFactory().getConnection()拿到pool中的redisConnection后,就没有后续操作了,就是表示此时redis连接池中的链接在租用后还没有释放或者还给链接池。虽然业务已经处理完毕,redisConnection处于空闲状态,但是池中的redisConnection状态还没有回到空闲状态。这个问题应该是正常的。已经找到总结:springstringRedisTemplate对redis的常规操作做了一些封装,但是不支持像ScanSetNx这样的命令。这时候需要获取一些特殊命令的jedisConnection。不推荐使用stringRedisTemplate.getConnectionFactory().getConnection()我们可以使用stringRedisTemplate.execute(newRedisCallback(){@OverridepublicCursordoInRedis(RedisConnectionconnection)throwsDataAccessException{returnconnection.scan(options);}});执行,或在使用连接后,使用RedisConnectionUtils.releaseConnection(conn,factory);释放连接。同时,不推荐在redis中使用keys命令。redispool的配置要搭配得当。否则,出现问题时,没有错误日志,也没有错误报告,定位难度很大。