redis optimization based on redisson

背景

周一大早上过来，发现在客户在jira上新建了一个bug卡。点进去一看原来是一个performance的issue，配图是NR中监控到redis的cpu直接被拉满的metric，这个问题应该困扰了团队很久。之前出现问题的时候，在staging中使用jmeter压测过很多次，都没有复现像生产上的问题。由于出现了几次，客户这次可能还是想找到根因吧。接着我早上接下了这张卡，开始了redis性能瓶颈的“调优之旅”。其中找到问题的过程还是挺有意思的，所以写下了这篇博客来分享给大家。不管怎么说还是要<span style='color:yellow'>敬畏生产！！！希望能给到大家一些借鉴。

在调优之前收集到的线索

• 线索一：app在NR上被采样到错误日志中的 Caused by: org.redisson.client.RedisTimeoutException: Subscription timeout after 3000ms. Check network and/or increase 'timeout' parameter.
• 线索二：app在NR上采集到的错误日志中的 Unable to load value by key xxx for map xxx_map
• 线索三：memoryDB中的metric，当出现性能瓶颈的时候，redis的 currConnection到达了3.2k
• 线索四：NR错误日志中，stack_trace中显示了代码中出现报错的具体函数的行数

寻找问题之路

出航

因为之前没有参与到这部分业务的开发，想着如果要彻底解决这个问题应该要把这个功能涉及到的代码都撸一遍。看完代码之后给大家总结一下，当前功能主要想使用 Redisson中提供的 LocalCacheMap来实现本地缓存，从而防止redis被高频访问而击穿。并且在当前项目还是用了webflux这类基于reactor的NIO的web框架，将local Cache中的value还会缓存在每一个Mono的pipeline的context中，以此来减少对内存缓存的调用。如上图所示，这里有这么多层保护，redis是怎么被击穿的啊，真叫人头大。根据最直观的<strong style='color:red'>线索四</strong>，我们直接看到的是给Redisson提供的 MapLoader接口实现类中一段加了分布式锁的代码。在充斥着reactor编程习惯的项目中，看见对Mono对象进行block操作，有了一个先入为主的<strong style='color:yellow'>假想一</strong>，<u>是不是因为这里有高并发，所有的线程都在抢这个锁的时候无法及时的释放资源，最终导致了死锁</u>。所以这时我们继续追看源码，发现Redisson在做load操作的时候自身就已经加锁了，所以我们自己代码中🔐是不是多余了。基于这两个现象，我越来越肯定是这个🔐导致的问题。所以我们在这里做了一下四组实验：

• 保持当前同步loader的实现和保留🔐，出现了异常 Subscription timeout after 3000ms. Check network and/or increase 'timeout' parameter
• 保持当前同步loader的实现和去掉🔐，<span style='color:green'>程序有时候会崩掉【大家在这里要留意一下这个，我当时没想太多】
• 使用Redisson提供的MapLoaderAsync中异步loader的实现和保留🔐，也出现了异常 Operator called default onErrorDropped, stacktrace: RedisTimeoutException: Command still hasn't been written into connection
• 使用Redisson提供的MapLoaderAsync中异步loader的实现和去掉🔐，程序未出现问题
  上述实验都是用本机开多线程得到的结果，我越来越觉得这个同步（block了mono的操作）以及多余的🔐是导致当前问题的关键。看到这个结果之后，我们在staging上部署实验四的代码并使用jmeter测试进行测试，测试的时候并没有看到错误日志。但是当时tps和rps并没有上去，所以一直以为是staging的压测能力不够【<span style='color:green'>这个时候QA给了一个结论，你们要先提高系统的性能，压测的并发才能上去，当时并不能理解这段话】。这个时候给出了一个分析分档，认为主要原因是同步🔐以及重复影响了性能。

再次起航

客户看了文档之后，他说会继续keep这个问题，并表示了感谢。在他check的过程中，我发现自己还是没有说服自己为啥这个同步🔐为啥会导致程序崩了，怀着这态度我继续探究了一番。并且让小伙伴在Mono的后面加上了一个doOnError之后再压测一次看看是否会出现错误，这次发现程序每次都进入了loader方法，也就是说local的缓存都没有命中。同时自己也做了一些本地的测试，将 LocalCachedMapOptions的storeMode设置成 LOACLCACHE，和生产app中保持一致。这个配置就是完全本地的存储，不会将数据存入redis。

public class RedissonLocalCacheMapTests {  
    private RedissonReactiveClient redissonReactiveClient;  
  
    private LocalCachedMapOptions localCachedMapOptions;  
  
    public RedissonLocalCacheMapTests() throws IOException {  
        String filePath = getClass().getClassLoader().getResource("config.yaml").getPath();  
        redissonReactiveClient = Redisson  
                .create(Config.fromYAML(new String(Files.readAllBytes(Paths.get(filePath)))))  
                .reactive();  
        localCachedMapOptions = LocalCachedMapOptions  
                .name("localCacheMap")  
.storeMode(LocalCachedMapOptions.StoreMode.LOCALCACHE)  
                .cacheSize(100)
                .timeToLive(Duration.ofSeconds(10))  
                .loader(new MyMapLoader());  
    }  
  
    @Test  
    void createLocalCacheMap() throws InterruptedException {  
        RLocalCachedMapReactive<String, String> localCachedMap = redissonReactiveClient.getLocalCachedMap(localCachedMapOptions);  
  
        while (true) {  
            Thread.sleep(5000L);              System.out.println(localCachedMap.get("key1").block());  
        }  
    } 
  
    class MyMapLoader implements MapLoader {  
  
        @Override  
        public Object load(Object key) {  
            System.out.println("load data from loader at first");  
            return "key1-value";
        }  
  
        @Override  
        public Iterable loadAllKeys() {  
            return List.of("localCache");  
        }  
    }  
}

根据上述代码，我理解当程序调用 RLocalCachedMapReactive的get方法会直接查询redis的键空间是否存在，如果不存在就会调用loader的实现类来获取original数据，然而我们使用的是 LOCALCACHE的存储模式，redis中永远都不会存储数据。于此同时 RLocalCachedMapReactive还提供了一个getCacheMap方法，这时我想是不是只要调用get方法才会去消费redis中的数据，然后再把数据存到cacheMap中。所以这个时候又得出<strong style='color:yellow'>假想二</strong>，<u>get方法用错了，应该以下述的方式来调用，只有cacheMap是空的时候采取调用get方法，这样就可以减少对laoder的调用，这样多线程就不会因为load方法中的lock的block而造成死锁。</u>

if (localCachedMap.getCachedMap().isEmpty())  
    System.out.println(localCachedMap.get("key1").block());  
System.out.println(localCachedMap.getCachedMap());

因为redisson的源码中也没有提供get和getCacheMap的实现代码，所以上述结论也是我的猜测。这时大佬提点了我一下，这个get应该是实现应该是下述的逻辑。所以我上述的猜测可能还是没有找到根因，所以我又继续探索。。。

if local cache exists
	return value
if local cache not exists
	check redis
	if key exists in redis
		return value and save to local cache
	if key not exists in redis
		trigger loader and save to local cache

再再次起航

在我的测试中，如果只运行一个测试来消费localCacheMap，那么只有在local cache在ttl到期的时候才会调用loader。但是再添加一个相同的测试之后，两个测试都在不停地调用loader😯，原来只有在两个线程同时消费同一个localcache的时候，才会引发这个问题。各种猜测就来了，<span style='color:green'>明明redis中没有这个key，都是在线程内部在维护这个cache，为什么两个线程就会相互影响？难道线程之间还会通信吗？难道这个cache是放到了一个共享的内存上吗？。大家还记得我之前提到过的<strong style='color:red'>线索一</strong>，以及Redisson中的文档中提到local cache会通过redis的key space event listen的方式来通知不同的线程来更新自己本地的数据。接着把Redisson的日志级别改成了trace，发现很多发布消息的日志。我明明使用的localCache的模式，为什么还会通知其他的消费者来保持数据的一致性？因为Redisson的配置默认的同步策略是 INVALIDTED【Invalidate local cache entry across all LocalCachedMap instances on map entry change. Broadcasts map entry hash (16 bytes) to all instances.】 人话就是，订阅当前键空间topic会清空当前的cache，并在下一次调用 RLocalCachedMapReactive.get(key)的时候会重新刷新Cache。然而LoaclCacheMap并不在redis，所以每次都会触发loader获取数据源。

2024.11.15 15:34:31.257 TRACE CommandPubSubDecoder : reply: *3 $7 message $18 {localCache}:topic $37 <9�C���^���_�ƘB����h�� , channel: [id: 0x6f5e1638, L:/127.0.0.1:62089 - R:127.0.0.1/127.0.0.1:6379], command: null 2024.11.15 15:34:31.258 DEBUG RedisExecutor : connection released for command: (PUBLISH), params: [{localCache}:topic, PooledUnsafeDirectByteBuf(ridx: 0, widx: 37, cap: 256)] from slot NodeSource [slot=0, addr=null, redisClient=null, redirect=null, entry=null] using connection RedisConnection@2097044822 [redisClient=[addr=redis://127.0.0.1:6379], channel=[id: 0xb0a3774f, L:/127.0.0.1:62092 - R:127.0.0.1/127.0.0.1:6379], currentCommand=CommandData [command=(PUBLISH), params: [{localCache}:topic, PooledUnsafeDirectByteBuf(ridx: 0, widx: 37, cap: 256)], promise: java.util.concurrent.CompletableFuture@211e417d[Completed normally], codec=org.redisson.client.codec.StringCodec], usage=0]

这次我又重新改变了我测试方案，使用了如下代码，每个一秒，并发数1w

@Test  
void localLoadTestToLocalCacheMap() {  
    RLocalCachedMapReactive<String, String> localCachedMap = redissonReactiveClient.getLocalCachedMap(localCachedMapOptions);  
  
    Flux.interval(Duration.ofSeconds(1))  
            .flatMap(x -> Flux.range(1, 10_000))  
            .parallel()  
            .flatMap(x -> localCachedMap.get("key1"))  
            .then()  
            .block();  
}

最后在运行了一段时间之后，程序发生了雪崩，redis都连不上了，下图是JVM的监控，在程序运行了2m之后就发生了崩溃并打出了如下的日志

Unable to acquire connection! java.util.concurrent.CompletableFuture@178b0321[Completed exceptionally: java.util.concurrent.CancellationException]Increase connection pool size or timeout. Node source: NodeSource [slot=0, addr=null, redisClient=null, redirect=null, entry=null], command: (HGET), params: [localCache, PooledUnsafeDirectByteBuf(ridx: 0, widx: 5, cap: 256)] after 0 retry attempts
org.redisson.client.RedisTimeoutException: Unable to acquire connection! java.util.concurrent.CompletableFuture@178b0321[Completed exceptionally: java.util.concurrent.CancellationException]Increase connection pool size or timeout. Node source: NodeSource [slot=0, addr=null, redisClient=null, redirect=null, entry=null], command: (HGET), params: [localCache, PooledUnsafeDirectByteBuf(ridx: 0, widx: 5, cap: 256)] after 0 retry attempts

当我把同步机制关掉之后，虽然容器内的redis的cpu使用率没有下来，但是程序没有崩溃，一直保持高cpu运行，如下图所示

再次证明了，如果只是调用loader并不会将redis的cpu拉满，而开启了同步模式 INVALIDATE，Redisson就会发布和订阅localCacheMap的topic。进而Redisson在接收到topic就会清空本地的Cache，导致local cache失效。大量redis的channel订阅和发布冗余操作，就会占用redis的连接和资源，最终导致系统的雪崩。retrieve value->publish message->clean local cache，周而复始资源占用叠加【如下图所示】，最后导致redis承受不了导致雪崩。

总结

根因

修改了 LocalCachedMapOptions 默认配置，storeMode LOCALCACHE和 syncStrategy INVALIDATE 不能同时使用。LocalCachedMapOptions 的 storeMode LOCALCACHE 和 syncStrategy INVALIDATE 配置在多实例环境下，导致每次请求数据时都要调用 loader，同时也增加了redission的 CPU 和网络占用率。

排查建议

• 先查看对应的metric，cpu的利用率，内存的使用量，看看是和到达峰值
• 检查系统的日志中心中的错误日志，查看是否能够看到有用的信息
• 通过查询当前slowlog来定位代码位置
• 查看代码中对redis有读写操作的部分，检查是否有可能出现高频的读写操作
• 如果在代码中有in-memory Cache，考虑是否是没有命中Local Cache，而是都把打到了redis上
• 在本地添加对应代码的测试压力测试来逐步缩小问题代码的范围，这里有个小tip，可以用reactor-core提供的方法来启动多线程的调用
• 打开问题代码块的trace log