记一次 Redis 不定时命中率降低问题调查

## 问题现象

-   后端服务获取用户令牌信息时有几率获取不到。
    这个处理是在 `Filter` 中执行的，在所有业务处理之前。
    采用 `StringRedisTemplate` 操作 Redis 缓存，令牌是个 `String` 类型的缓存。
    令牌缓存的 KEY 在 Redis 中是一直存在的，远没到过期时间。
-   获取不到令牌的请求，响应也很快，并不是由于 Redis 超时导致的。
-   使用同一台 Redis （db不同）的其它服务一切都是正常的，从没出现过类似问题。
-   线下的测试环境使用的自建 Redis ，并没有出现过这个问题。
-   出问题服务的容器镜像是 9 天前构建的。
-   服务重启之后会恢复正常，但不确定多长时间之后又会再次出现。
    重启后可能一天内都是好的，也可能几分钟之后就又出问题。
-   与此同时，Redis 性能监控中的命中率图表会出现明显的波动，与服务出问题的时间基本一致。
    命中率波动非常大，正常情况下一般在 95% 左右，但出问题时可能会降到 20% 以下。
    ![](/uploads/files/2022/1/24/20220124-maibu-redis-hit-rate.png)

## 问题调查

先说明下项目环境，服务端是 SpringBoot，使用 `StringRedisTemplate` 操作 Redis，使用的 *lettuce* 连接池。
Redis 服务器是阿里云的 2 节点集群版多分区版。

这里最令人费解的就是如果代码出了问题导致请求没有发送出去，那么 Redis 服务器应该不会有命中率降低的现象；
而如果请求确实是发送到了 Redis 服务器，由于 Key 是存在的，那么同样命中率也不会有降低才对。

为了调查问题原因，采取了一些方法，但一直没有找到原因，而且由于代码很久没有变动过，所以一度怀疑是 Redis 服务器的原因。

-   检查了相关的代码，最近 1 个月没有动过 Redis 或 `RedisTemplate` 相关的代码和配置。
    代码类似如下处理：
    ```java
    String tokenInfo = stringRedisTemplate.opsForValue().get(token);
    if (StringUtils.isEmpty(tokenInfo)) {
        log.error("TokenFilter TokenNotExist {} {}", token, request.getRequestURI());
        return;
    }
    ```
-   采用请求重放的方式，确认了即使是相同的请求，也有一定几率出现这个问题。
    这里用了 jMeter 重放请求。
-   打印了日志，发现服务段获取到的令牌参数是对的。
-   以为是 Redis 服务器的问题，找了阿里云客服，最后发现服务器并没有什么异常。
-   后让采用抓包的方式（Pod 和 宿主节点），看一下服务发送的请求内容，但由于运维当时已经回家过年啦，就没执行。
    现在回想起来，如果当时抓包的话，应该是有助于发现问题原因的。
-   以为是 Redis 连接池中的连接问题，修改了 *lettuce* 线程池的配置，将最低空闲连接数量修改成了 0。
-   修改了 Redis *timeout* 配置（超过次空闲时间将断开连接），从 0 （永不断开）修改为 60（空闲超过 60 秒断开连接）。
-   在获取不到令牌信息时，立即尝试重复获取（最多 3 次），但发现若获取不到，则连续的 3 次都获取不到。
-   以为是多分区 Redis 服务器的原因，后来采用 DTS 的方式无缝切换成了单分区的 Redis ，本因为已经好了，但隔天又出现问题。
    阿里云的 DTS 不知道什么时候开始已支持 Redis 同步。
    记得之前切换 Redis ，从备份开始再恢复备份到一台新的 Redis 实例，大概要花费半个小时以上的时间。
    现在切换基本上是无缝的，只要修改配置后重新部署容器就行了。

上述调查持续了近一周的时间，最后偶然间想到会不会是我别的处理中曾经用过 Redis 事务的原因。
在启用了 `RedisTemplate.multi` 之后，之后的请求并不会立即执行，返回的就是 *null* ，和获取时的现象有点像。
但令牌获取的处理中并没有调用 `multi` 方法，于是查看了 `multi` 方法的实现。

```java
/*
 * (non-Javadoc)
 * @see org.springframework.data.redis.core.RedisOperations#multi()
 */
@Override
public void multi() {
    execute(connection -> {
        connection.multi();
        return null;
    }, true);
}
```

可以看到这里调用了 *connection* 的 `multi` 方法，正是这里改变了 *connection* 的状态，而连接池会保持连接，从而导致所有使用这个连接的都可能会出问题。

不知道为什么我这里没有 Javadoc 文档，同事的电脑上有文档说明，上面写了调用了该方法，必须调用 `exec` 或 `discard` 方法。
本次问题的根源应该就在这里，因为代码的缺陷，导致没有执行到这两个方法。

另外需要注意 `execute` 的第二个参数，这里是 `true` ，这个参数表示是否公开 Redis 连接给调用的方法。
猜测如果这个值是 `false` ，应该也不会发生此次的问题。

由于默认使用的 *lettuce* 连接池，这里连接的实例是 `LettuceConnection` ，其 `multi` 和 `isQueueing` 方法代码如下：

```java
@Override
public void multi() {
    if (isQueueing()) {
        return;
    }
    isMulti = true;
    try {
        if (isPipelined()) {
            getAsyncDedicatedRedisCommands().multi();
            return;
        }
        getDedicatedRedisCommands().multi();
    } catch (Exception ex) {
        throw convertLettuceAccessException(ex);
    }
}

/*
 * (non-Javadoc)
 * @see org.springframework.data.redis.connection.RedisConnection#isQueueing()
 */
@Override
public boolean isQueueing() {
    return isMulti;
}
```

正是在这个方法中改变了 *connection* 的状态。

另外，`LettuceStringCommands` 的 `get` 方法代码如下：

```java
/*
 * (non-Javadoc)
 * @see org.springframework.data.redis.connection.RedisStringCommands#get(byte[])
 */
@Override
public byte[] get(byte[] key) {

Assert.notNull(key, "Key must not be null!");

try {
        if (isPipelined()) {
            pipeline(connection.newLettuceResult(getAsyncConnection().get(key)));
            return null;
        }
        if (isQueueing()) {
            transaction(connection.newLettuceResult(getAsyncConnection().get(key)));
            return null;
        }
        return getConnection().get(key);
    } catch (Exception ex) {
        throw convertLettuceAccessException(ex);
    }
}
```

此时 `isQueueing()` 为 `true` ，这也就解释了，为什么 Redis 中明明有这个缓存， `StringRedisTemplate.get` 方法却返回的是 `null` 了。

再看下 `LettuceConnection.exec` 方法，在此将 `isMulti` 重置为了 `false` 。
而如果因为异常等原因导致该方法没被调用，则该连接的 `isMulti` 将一直是 `true`，直到下一次 `exec` 方法的调用。

```java
@Override
@SuppressWarnings({ "unchecked", "rawtypes" })
public List<Object> exec() {

isMulti = false;

try {
        if (isPipelined()) {
            RedisFuture<TransactionResult> exec = getAsyncDedicatedRedisCommands().exec();

LettuceTransactionResultConverter resultConverter = new LettuceTransactionResultConverter(
                    new LinkedList<>(txResults), LettuceConverters.exceptionConverter());

pipeline(newLettuceResult(exec, source -> resultConverter
                    .convert(LettuceConverters.transactionResultUnwrapper().convert((TransactionResult) source))));
            return null;
        }

TransactionResult transactionResult = (getDedicatedRedisCommands()).exec();
        List<Object> results = LettuceConverters.transactionResultUnwrapper().convert(transactionResult);
        return convertPipelineAndTxResults
                ? new LettuceTransactionResultConverter(txResults, LettuceConverters.exceptionConverter()).convert(results)
                : results;
    } catch (Exception ex) {
        throw convertLettuceAccessException(ex);
    } finally {
        txResults.clear();
    }
}
```

下面是 `discard` 方法，这里也会将 `isMulti` 置为 `false` ，并丢弃队列中的任务。

```java
@Override
public void discard() {
    isMulti = false;
    try {
        if (isPipelined()) {
            pipeline(newLettuceStatusResult(getAsyncDedicatedRedisCommands().discard()));
            return;
        }
        getDedicatedRedisCommands().discard();
    } catch (Exception ex) {
        throw convertLettuceAccessException(ex);
    } finally {
        txResults.clear();
    }
}
```

下面是事后写的两个测试方法，`multi` 的正确用法可以参考第二个方法，应该使用 `catch` 和 `finally` 确保事务的关闭。

```java
@Test
void should_null_when_not_discard_in_catch() {
    String key = "test_key";
    String setValue = "test_value";

stringRedisTemplate.opsForValue().set(key, setValue);

try {
        stringRedisTemplate.setEnableTransactionSupport(true);
        stringRedisTemplate.multi();

throw new Exception("");

// stringRedisTemplate.exec();
    } catch (Exception ex) {
        // stringRedisTemplate.discard();
    } finally {
        stringRedisTemplate.setEnableTransactionSupport(false);
    }

String getValue = stringRedisTemplate.opsForValue().get(key);

Assertions.assertNull(getValue);
}

@Test
void should_not_null_when_discard_in_catch() {
    String key = "test_key";
    String setValue = "test_value";

stringRedisTemplate.opsForValue().set(key, setValue);

try {
        stringRedisTemplate.setEnableTransactionSupport(true);
        stringRedisTemplate.multi();

throw new Exception("");

// stringRedisTemplate.exec();
    } catch (Exception ex) {
        stringRedisTemplate.discard();
    } finally {
        stringRedisTemplate.setEnableTransactionSupport(false);
    }

String getValue = stringRedisTemplate.opsForValue().get(key);

Assertions.assertNotNull(getValue);
    Assertions.assertEquals(getValue, setValue);
}
```

## 对策

修改前代码如下：

```java
stringRedisTemplate.setEnableTransactionSupport(true);
stringRedisTemplate.multi();
// do some redis operations
stringRedisTemplate.exec();
stringRedisTemplate.setEnableTransactionSupport(false);
```

虽然暂时还不知道什么原因导致的 `exec` 方法没有调用（没有看到任何相关的错误日志，而且这段代码运行了有近半年了），但是能说明至今出现的所有现象。
特别是命中率的问题，虽然 Key 存在，但由于获取时仅仅只是将获取的任务放到了命令队列中，而在执行时，这些任务可能会被分配到不存在这个 Key 的节点（Redis 是集群版），从而导致出现了命中率降低的现象。
这也可以解释为什么服务重启之后一切就都正常了，为什么出现问题的时间不确定，为什么重复多次获取总是失败。

这也侧面说明了，代码没有出现问题，不代表没有问题。
=。=|||

知道问题在哪里就好修改了，参考上面的第二个测试方法，在使用 `multi` 命令时，确保其被执行或取消就行了，另外事务也需要确保被关闭。

```java
try {
    stringRedisTemplate.setEnableTransactionSupport(true);
    stringRedisTemplate.multi();

// do some redis operations

stringRedisTemplate.exec();
} catch (Exception ex) {
    stringRedisTemplate.discard();
} finally {
    stringRedisTemplate.setEnableTransactionSupport(false);
}
```

记一次 Redis 不定时命中率降低问题调查

目录

关联

热门

最新