记一次 Redis 不定时命中率降低问题调查
🏷️ Redis
问题现象
后端服务获取用户令牌信息时有几率获取不到。
这个处理是在Filter
中执行的,在所有业务处理之前。
采用StringRedisTemplate
操作 Redis 缓存,令牌是个String
类型的缓存。
令牌缓存的 KEY 在 Redis 中是一直存在的,远没到过期时间。获取不到令牌的请求,响应也很快,并不是由于 Redis 超时导致的。
使用同一台 Redis(db 不同)的其它服务一切都是正常的,从没出现过类似问题。
线下的测试环境使用的自建 Redis,并没有出现过这个问题。
出问题服务的容器镜像是 9 天前构建的。
服务重启之后会恢复正常,但不确定多长时间之后又会再次出现。
重启后可能一天内都是好的,也可能几分钟之后就又出问题。与此同时,Redis 性能监控中的命中率图表会出现明显的波动,与服务出问题的时间基本一致。
命中率波动非常大,正常情况下一般在 95% 左右,但出问题时可能会降到 20% 以下。
问题调查
先说明下项目环境,服务端是 SpringBoot,使用 StringRedisTemplate
操作 Redis,使用的 lettuce 连接池。
Redis 服务器是阿里云的 2 节点集群版多分区版。
这里最令人费解的就是如果代码出了问题导致请求没有发送出去,那么 Redis 服务器应该不会有命中率降低的现象;
而如果请求确实是发送到了 Redis 服务器,由于 Key 是存在的,那么同样命中率也不会有降低才对。
为了调查问题原因,采取了一些方法,但一直没有找到原因,而且由于代码很久没有变动过,所以一度怀疑是 Redis 服务器的原因。
- 检查了相关的代码,最近 1 个月没有动过 Redis 或
RedisTemplate
相关的代码和配置。
代码类似如下处理:javaString tokenInfo = stringRedisTemplate.opsForValue().get(token); if (StringUtils.isEmpty(tokenInfo)) { log.error("TokenFilter TokenNotExist {} {}", token, request.getRequestURI()); return; }
1
2
3
4
5 - 采用请求重放的方式,确认了即使是相同的请求,也有一定几率出现这个问题。
这里用了 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
方法的实现。
/*
* (non-Javadoc)
* @see org.springframework.data.redis.core.RedisOperations#multi()
*/
@Override
public void multi() {
execute(connection -> {
connection.multi();
return null;
}, true);
}
2
3
4
5
6
7
8
9
10
11
可以看到这里调用了 connection 的 multi
方法,正是这里改变了 connection 的状态,而连接池会保持连接,从而导致所有使用这个连接的都可能会出问题。
不知道为什么我这里没有 Javadoc 文档,同事的电脑上有文档说明,上面写了调用了该方法,必须调用 exec
或 discard
方法。
本次问题的根源应该就在这里,因为代码的缺陷,导致没有执行到这两个方法。
另外需要注意 execute
的第二个参数,这里是 true
,这个参数表示是否公开 Redis 连接给调用的方法。
猜测如果这个值是 false
,应该也不会发生此次的问题。
由于默认使用的 lettuce 连接池,这里连接的实例是 LettuceConnection
,其 multi
和 isQueueing
方法代码如下:
@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;
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
正是在这个方法中改变了 connection 的状态。
另外,LettuceStringCommands
的 get
方法代码如下:
/*
* (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);
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
此时 isQueueing()
为 true
,这也就解释了,为什么 Redis 中明明有这个缓存, StringRedisTemplate.get
方法却返回的是 null
了。
再看下 LettuceConnection.exec
方法,在此将 isMulti
重置为了 false
。
而如果因为异常等原因导致该方法没被调用,则该连接的 isMulti
将一直是 true
,直到下一次 exec
方法的调用。
@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();
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
下面是 discard
方法,这里也会将 isMulti
置为 false
,并丢弃队列中的任务。
@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();
}
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
下面是事后写的两个测试方法,multi
的正确用法可以参考第二个方法,应该使用 catch
和 finally
确保事务的关闭。
@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);
}
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
对策
修改前代码如下:
stringRedisTemplate.setEnableTransactionSupport(true);
stringRedisTemplate.multi();
// do some redis operations
stringRedisTemplate.exec();
stringRedisTemplate.setEnableTransactionSupport(false);
2
3
4
5
虽然暂时还不知道什么原因导致的 exec
方法没有调用(没有看到任何相关的错误日志,而且这段代码运行了有近半年了),但是能说明至今出现的所有现象。
特别是命中率的问题,虽然 Key 存在,但由于获取时仅仅只是将获取的任务放到了命令队列中,而在执行时,这些任务可能会被分配到不存在这个 Key 的节点(Redis 是集群版),从而导致出现了命中率降低的现象。
这也可以解释为什么服务重启之后一切就都正常了,为什么出现问题的时间不确定,为什么重复多次获取总是失败。
这也侧面说明了,代码没有出现问题,不代表没有问题。
=。=|||
知道问题在哪里就好修改了,参考上面的第二个测试方法,在使用 multi
命令时,确保其被执行或取消就行了,另外事务也需要确保被关闭。
try {
stringRedisTemplate.setEnableTransactionSupport(true);
stringRedisTemplate.multi();
// do some redis operations
stringRedisTemplate.exec();
} catch (Exception ex) {
stringRedisTemplate.discard();
} finally {
stringRedisTemplate.setEnableTransactionSupport(false);
}
2
3
4
5
6
7
8
9
10
11
12