填坑之路-记录Redis操作的异常QueryTimeoutException & RedisCommandTimeoutException: Command timed out after 1 min

原始异常信息如下org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)at org.springframew

汉风唐尚

15698人浏览 · 2021-12-26 17:16:43

汉风唐尚 · 2021-12-26 17:16:43 发布

默认配置

1.命令执行的默认超时时间为1分钟
2.默认的Lettuce集群配置里面才有命令执行超时时间，源码请看：LettuceConnectionFactory
3.修改命令超时时间，请手动修改配置构造器中的配置：LettucePoolingClientConfiguration.LettucePoolingClientConfigurationBuilder 中的setCommandTime

原始异常信息如下

org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)
        at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
        at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
        at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
        at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
        at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:269)
        at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:799)
        at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:68)
        at org.springframework.data.redis.connection.DefaultedRedisConnection.get(DefaultedRedisConnection.java:260)
        at org.springframework.data.redis.core.DefaultValueOperations$1.inRedis(DefaultValueOperations.java:57)
        at org.springframework.data.redis.core.AbstractOperations$ValueDeserializingRedisCallback.doInRedis(AbstractOperations.java:60)
        at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:228)
        at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:188)
        at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:96)
        at org.springframework.data.redis.core.DefaultValueOperations.get(DefaultValueOperations.java:53)
        at com.vevor.crm.service.base.DictBizServiceImpl.getDictList(DictBizServiceImpl.java:240)
        at com.vevor.crm.service.base.DictBizServiceImpl.getKey(DictBizServiceImpl.java:145)
        at com.vevor.crm.task.walmart.WalmartProductTask.convertToCommonProduct(WalmartProductTask.java:107)
        at com.vevor.crm.task.walmart.WalmartProductTask.pullWalmartProduct(WalmartProductTask.java:85)
        at com.vevor.crm.task.AllTaskServiceImpl.pullWalmartProduct(AllTaskServiceImpl.java:452)
        at com.vevor.crm.task.AllTaskServiceImpl$$FastClassBySpringCGLIB$$28033197.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:769)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
        at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88)
        at org.springframework.cloud.sleuth.instrument.async.TraceAsyncAspect.traceBackgroundThread(TraceAsyncAspect.java:67)
        at sun.reflect.GeneratedMethodAccessor273.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
        at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
        at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:747)
        at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at org.springframework.cloud.sleuth.instrument.async.TraceRunnable.run(TraceRunnable.java:67)
        at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)
        at io.lettuce.core.ExceptionFactory.createTimeoutException(ExceptionFactory.java:51)
        at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:114)
        at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:69)
        at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
        at com.sun.proxy.$Proxy440.get(Unknown Source)
        at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:66)
        ... 34 common frames omitted

问题定位，三连击

什么是：QueryTimeoutException
什么是：RedisCommandTimeoutException
为什么百度都说换成Jedis

个人理解：
Redis命令执行超时了而已；

Redis超时的分类

Redis命令超时分为客户端超时和服务端超时。

1.客户端超时时间一般由客户端代码自行控制，业务侧需要根据自己的业务特点选择合适的超时时间（例如Java的Lettuce客户端，该参数名为timeout）。
2.Redis服务端Timeout默认配置为0，不会主动断开连接

开始定位超时问题

1.将Redis配置加入bootstrap.yml文件中
在这里插入图片描述
想要看属性请按住：ctrl+鼠标左键；即可进入对应的类中
2.找到超时的配置属性：timeout

3.随手一个测试代码，多线程的


    @PostConstruct
    public void test() {
        List<String> dataList = new ArrayList<>(1000);
        for (int i = 0; i < 1000; i++) {
            dataList.add("testStr:" + i);
        }
        // 线程池，多线程执行
        BlockingQueue<Runnable> threads = new ArrayBlockingQueue<Runnable>(1000);
        ThreadPoolExecutor threadPoolExecutor = new ThreadPoolExecutor(10, 20, 300L, TimeUnit.SECONDS, threads);

        for (int i = 0; i < 1000; i++) {
            String key = "key" + i;
            threadPoolExecutor.execute(() -> {
                System.out.println("操作" + key);
                redisTemplate.opsForSet().add(key, dataList);
                System.out.println(redisTemplate.opsForSet().members(key));
            });
        }

        System.out.println("done");
    }

4.执行结果统计
4.1.第一把执行
没有任何错误，贼快！
在这里插入图片描述
4.2.觉得和预期不一样，确认有无配置成功

跟进一下代码，发现是给Redis建立链接的时候用的

仔细看下代码，发现这个timeout时间压根没用

我用的是Lettuce连接池，结果发现这玩意压根没有用timeout的配置，搞毛线！
在这里插入图片描述

4.3.没辙了，只好根据日志提示信息翻过来找

Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 1 minute(s)
        at io.lettuce.core.ExceptionFactory.createTimeoutException(ExceptionFactory.java:51)
        at io.lettuce.core.LettuceFutures.awaitOrCancel(LettuceFutures.java:114)
        at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:69)
        at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
        at com.sun.proxy.$Proxy440.get(Unknown Source)
        at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:66)
        ... 34 common frames omitted

在这里插入图片描述

终于发现报错的地方的！居然是获取链接的地方挂了，链接类型：LettuceConnection

返现Lettuce里面有超时配置，但是这个到底是链接超时的还是命令执行超时呢，还不清楚：

好好翻一下链接的工厂类，发现了配置项，咱搜一下timeout的作用！
在这里插入图片描述
狐狸尾巴漏出来了，找到了commandTimeout

依旧没有发现是能配置的地方，开始思考自己的配置是否正确了；感觉自己没按照正常的配置来了
继续检查我的配置，开始翻看配置的构造了

4.4.终于发现了，配置的隐藏位置：
在这里插入图片描述

最后修改

一下是我自己的链接工厂配置

        /* ========= 连接池通用配置 ========= */
        GenericObjectPoolConfig<Object> genericObjectPoolConfig = new GenericObjectPoolConfig<>();
        genericObjectPoolConfig.setMaxTotal(maxActive);
        genericObjectPoolConfig.setMinIdle(minIdle);
        genericObjectPoolConfig.setMaxIdle(maxIdle);
        genericObjectPoolConfig.setMaxWaitMillis(maxWait);

        /* ========= lettuce pool ========= */
        LettucePoolingClientConfiguration.LettucePoolingClientConfigurationBuilder builder = LettucePoolingClientConfiguration.builder();
        builder.poolConfig(genericObjectPoolConfig);
        // 这才是最关键的一段
        builder.commandTimeout(Duration.ofMillis(commandTimeout));
        LettuceConnectionFactory connectionFactory = new LettuceConnectionFactory(redisStandaloneConfiguration, builder.build());
        connectionFactory.setDatabase(database);
        connectionFactory.afterPropertiesSet();

这个位置增加一下命令执行时间就好，你想让多久命令超时就多久超时！
根本原因有两个：
1.Redis大key，高频搜，偶发性的报错；
2.value存的大，导致搜索的时候数据返回慢；可自行用RedisDesktopManager查看存的内容大小！
总结：
redis本身很快，但是不规范的使用会导致各种异常；百度的资料有些让切换Jedis，但是这个改造成本不觉得有点大嘛！