ToB企服应用市场:ToB评测及商务社交产业平台

标题: （已解决）io.lettuce.core.RedisCommandTimeoutException: Command timed [打印本页]
作者: 来自云龙湖轮廓分明的月亮    时间: 2024-12-10 10:04
标题: （已解决）io.lettuce.core.RedisCommandTimeoutException: Command timed

项目版本

spingboot使用2.3.4.RELEASE，内置的lettuce版本为5.3.4.RELEASE
服务为容器化部署，redis裸机部署
redis是单节点（生产情况redis使用sentinel集群，未出现此类问题）
问题描述

   org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeou
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.38.jar:4.0.FR]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.springframework.web.filter.ForwardedHeaderFilter.doFilterInternal(ForwardedHeaderFilter.java:149) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.2.9.RELEASE.jar:5.2.9.RELEASE]
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.coyote.AbstractProtocol                                        C                            o                            n                            n                            e                            c                            t                            i                            o                            n                            H                            a                            n                            d                            l                            e                            r                            .                            p                            r                            o                            c                            e                            s                            s                            (                            A                            b                            s                            t                            r                            a                            c                            t                            P                            r                            o                            t                            o                            c                            o                            l                            .                            j                            a                            v                            a                            :                            868                            )                                                         [                            t                            o                            m                            c                            a                            t                            −                            e                            m                            b                            e                            d                            −                            c                            o                            r                            e                            −                            9.0.38.                            j                            a                            r                            :                            9.0.38                            ]                            a                            t                            o                            r                            g                            .                            a                            p                            a                            c                            h                            e                            .                            t                            o                            m                            c                            a                            t                            .                            u                            t                            i                            l                            .                            n                            e                            t                            .                            N                            i                            o                            E                            n                            d                            p                            o                            i                            n                            t                                  ConnectionHandler.process(AbstractProtocol.java:868) ~[tomcat-embed-core-9.0.38.jar:9.0.38] at org.apache.tomcat.util.net.NioEndpoint                     ConnectionHandler.process(AbstractProtocol.java:868) [tomcat−embed−core−9.0.38.jar:9.0.38]atorg.apache.tomcat.util.net.NioEndpointSocketProcessor.doRun(NioEndpoint.java:1590) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_275]
at java.util.concurrent.ThreadPoolExecutor                                        W                            o                            r                            k                            e                            r                            .                            r                            u                            n                            (                            T                            h                            r                            e                            a                            d                            P                            o                            o                            l                            E                            x                            e                            c                            u                            t                            o                            r                            .                            j                            a                            v                            a                            :                            624                            )                                                         [                            ?                            :                            1.8.                                       0                               2                                      75                            ]                            a                            t                            o                            r                            g                            .                            a                            p                            a                            c                            h                            e                            .                            t                            o                            m                            c                            a                            t                            .                            u                            t                            i                            l                            .                            t                            h                            r                            e                            a                            d                            s                            .                            T                            a                            s                            k                            T                            h                            r                            e                            a                            d                                  Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_275] at org.apache.tomcat.util.threads.TaskThread                     Worker.run(ThreadPoolExecutor.java:624) [?:1.8.02​75]atorg.apache.tomcat.util.threads.TaskThreadWrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.38.jar:9.0.38]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_275]
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 10 second(s)
at io.lettuce.core.ExceptionFactory.createTimeoutException(ExceptionFactory.java:51) ~[lettuce-core-5.3.4.RELEASE.jar:5.3.4.RELEASE]
at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:119) ~[lettuce-core-5.3.4.RELEASE.jar:5.3.4.RELEASE]
at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:75) ~[lettuce-core-5.3.4.RELEASE.jar:5.3.4.RELEASE]
at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:79) ~[lettuce-core-5.3.4.RELEASE.jar:5.3.4.RELEASE]
at com.sun.proxy.$Proxy191.get(Unknown Source) ~[?:?]
at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:66) ~[spring-data-redis-2.3.4.RELEASE.jar:2.3.4.RELEASE]
… 64 more
   看现象盲猜：服务器对长时间不活跃的连接举行了关闭，而客户端没有探活机制，一直在持有旧连接，有请求的时候由于服务端已经关闭了连接导致客户端超时，lettuce的重试机制新建连接，最后恢复。
ps:一开始也猜测过服务器的负载过大导致redis实行超时，但是查询过服务器的负载发现并不高，同时本地redis客户端连接查询速度都非常快，因此排除负载问题。
解决步骤

第一步

我的项目中lettuce配置为：
  1. spring.redis.database=0
  2. spring.redis.lettuce.pool.max-active=16
  3. spring.redis.lettuce.pool.min-idle=0
  4. spring.redis.lettuce.pool.max-wait=5000
  5. spring.redis.lettuce.pool.max-idle=20
  6. spring.redis.timeout=1200
  7. spring.redis.lettuce.pool.time-between-eviction-runs=1000
  9. 修改为
  10. spring.redis.lettuce.pool.min-idle=1
  11. 增加,以下两个配置理论上只对cluster集群的redis生效，我测试为单节点，所以可能没有用，考虑到有同学是这个场景，可以尝试
  12. spring.redis.lettuce.cluster.refresh.adaptive=true
  13. spring.redis.lettuce.cluster.refresh.period=10s
复制代码
首先猜疑min-idle的值设置不合理，改为1，同时增加连接刷新的配置，持续观察。
观察结果：redis连接超时非常仍旧会有，但是接口恢复速度明显提升。以前三五分钟才会恢复，调整后第一次非常，秒级的第二三次查询会恢复 。
第二步（此操纵有效！！！）

若第一步无效，则在redisTemplate的bean中对lettuceConnectionFactory增加validateConnection属性设置。
源码中是在获取连接时如果连接中断则更新连接，不确定在连接保持的时候是否能够 持续 查验并更新连接，而非在获取连接时的 一次性 校验。如果不行，大概须要手动写定时任务做连接校验，但是这种实现太丑了。
当然，如果就算是在获取连接时的一次性校验，只要校验效率足够高，能够毫秒级的完成校验及连接更新，在用户感知上趋近于无，且不触发上述非常，则最好。

  1.     @Bean
  2.     public RedisTemplate<String, Object> redisTemplate(LettuceConnectionFactory lettuceConnectionFactory) {
  3.                 // 重点
  4.         lettuceConnectionFactory.setValidateConnection(true);
  5.         
  6.         RedisTemplate<String, Object> redisTemplate = new RedisTemplate<>();
  7.         redisTemplate.setConnectionFactory(lettuceConnectionFactory);
  8.         redisTemplate.setKeySerializer(new StringRedisSerializer());
  9.         redisTemplate.setHashKeySerializer(new StringRedisSerializer());
  10.         redisTemplate.setValueSerializer(new JdkSerializationRedisSerializer());
  11.         redisTemplate.setHashValueSerializer(new JdkSerializationRedisSerializer());
  12.         redisTemplate.afterPropertiesSet();
  14.         return redisTemplate;
  15.     }
复制代码
观察结果：redis连接超时非常已消失，接口均正常。但是第一次请求时接口相应明显慢，后续均正常
服务前期已接入pinpoint，通过pinpoint请求调用分析，可以明显看到，连接确实是已经断开，但是因为我们有ValidateConnection的连接校验逻辑，ping的时候没有相应，因此更新了连接，后续的服务逻辑实行没有碰到非常了。


后续的接口正常实行是毫秒级的耗时：

缘故原由分析：
lettuce中的连接因为长时间空闲，因此被断开，这个断开的操纵不确定是服务端还是客户端发起的，后续有时间再深入研究吧。
这个也解释了为什么生产情况没有碰到这个问题，因为生产情况有大量且持续的请求，redis连接是活跃的，因此不存在连接因空闲被中断的问题。
测试情况访问量小且不连续（空闲时间多），导致连接被中断，造成了假死现象。目前使用不报错，只管长时间空闲后的第一次访问会因为连接查验+重置的操纵导致耗时增加，但是接口不会报错，后续逻辑均正常实行，在可接受范围内。
若小伙伴们仍以为初次连接的高耗时不可接受，那就写个定时任务，定时实行validateConnection()方法吧，保持lettuce连接池中的连接均活跃，我是不太喜好这么整。
极度方案

不嫌麻烦的话，可以把客户端换回jedis，jedis中带有探活逻辑。
20241114更新

别的一个服务同样碰到此问题，但加完lettuceConnectionFactory.setValidateConnection(true);之后，每次连接校验的时候都会报
  1. 2024-11-14 11:26:30.009|INFO  |9076|scheduling-1|org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$SharedConnection.validateConnection(LettuceConnectionFactory.java:1413)|Validation of shared connection failed. Creating a new connection.
复制代码
连接校验是ping的方式，超时阈值为10s，三个节点ping，导致我每次接口实行都会先耗费30s在redis的连接上，至于为什么会这样，暂时还没看出来缘故原由，跟其他服务对比之后，发现唯一的区别在于redis的pom版本不同，增加连接校验完之后正常的服务redis版本为2.3.4.RELEASE，非常版本为2.7.9。但是由于历史缘故原由，无法回退版本，因此接纳定时连接校验的方式来处理惩罚此问题
  1.     @Resource
  2.     private LettuceConnectionFactory connectionFactory;
  3.    
  4.     /**
  5.      * 每隔30s进行一次连接校验避免连接失效
  6.      */
  7.     @Scheduled(cron="0/30 * * * * ?")
  8.     public void task() {
  9.             log.info("=============连接校验开始=======");
  10.             connectionFactory.validateConnection();
  11.             log.info("=============连接校验结束=======");
  12.     }
复制代码
参考链接

先去github搜issue：
https://github.com/redis/lettuce/issues/2177
发现此issue跟我的现象一模一样，但是很遗憾没有解决方案。
https://github.com/redis/lettuce/issues/1428
讨论很多，比较深入
https://bbs.csdn.net/topics/392566194
有解决方案

免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！更多信息从访问主页：qidao123.com:ToB企服之家，中国第一个企服评测及商务社交产业平台。



欢迎光临 ToB企服应用市场:ToB评测及商务社交产业平台 (https://dis.qidao123.com/) Powered by Discuz! X3.4