实战-商品中心-l2cache高并发场景下出现OOM的分析和优化方案

白云coy

已于 2024-01-11 15:42:15 修改

阅读量1.2k

点赞数 2

CC 4.0 BY-SA版权

分类专栏： l2cache系列文章标签：缓存 redis 队列

于 2021-01-06 15:26:33 首次发布

本文链接：https://blog.csdn.net/icansoicrazy/article/details/112274052

l2cache系列专栏收录该内容

13 篇文章

订阅专栏

本文分析了一次电商平台在双十二压测期间商品中心出现OOM的问题。问题源于商品中心的缓存框架l2cache，在高并发场景下，同一key的大量refresh消息导致ForkJoinPool的无界队列堆积，进而引发OOM。优化方案包括：1) 控制同一key的refresh消息发送，如加分布式锁限制频率；2) 在消费消息侧过滤重复的refresh操作，使用AtomicInteger过滤并发刷新任务。这两个方案旨在解决队列堆积和重复消息问题，避免OOM。

摘要生成于 C知道，由 DeepSeek-R1 满血版支持，前往体验 >

l2cache 源码地址

概要：

为应对双十二活动，现对电商平台核心主链路进行压测，在压测过程中商品中心出现OOM。

压测环境的基本情况（只列出部分数据）：
1、商品中心：8核16G，120个pod
2、redis配置：192G读写分离版（32节点），单片带宽：192M
3、DB配置：PolarDB顶配（88核 710G，1主6从）
4、商品中心集成 l2cache 缓存框架（一级缓存：caffeine，二级缓存：redis）

问题

商品中心在压测时出现OOM，具体错误日志如下：

在这里插入图片描述

分析

1、通过上面的日志可得知，具体的错误点为：

com.github.benmanes.caffeine.cache.LocalLoadingCache.java:166

Exception thrown during refresh

2、分析caffeine源码 LocalLoadingCache

interface LocalLoadingCache<K, V> extends LocalManualCache<K, V>, LoadingCache<K, V> {
  // 省略无关代码 ...

  // refresh 方法的作用：异步加载key的新值。加载新值时，get（key）将继续返回以前的值（如果有），除非它被逐出
  default void refresh(K key) {
    requireNonNull(key);

    long[] writeTime = new long[1];
    long startTime = cache().statsTicker().read();
    V oldValue = cache().getIfPresentQuietly(key, writeTime);
    CompletableFuture<V> refreshFuture = (oldValue == null)
        ? cacheLoader().asyncLoad(key, cache().executor())
        : cacheLoader().asyncReload(key, oldValue, cache().executor());
    refreshFuture.whenComplete((newValue, error) -> {
      long loadTime = cache().statsTicker().read() - startTime;
      if (error != null) {
        // 关键的错误日志在这里
        logger.log(Level.WARNING, "Exception thrown during refresh", error);
        cache().statsCounter().recordLoadFailure(loadTime);
        return;
      }
  	// 省略无关代码 ...
  }
  // 省略无关代码 ...
}

通过上面的源码可知，关键的方法在 LocalLoadingCache.refresh()，所以继续排查l2cache里面有调用该方法的代码。

3、排查l2cache里面调用LocalLoadingCache.refresh()的代码

通过分析，发现有两处代码有调用，如下：

com.coy.l2cache.cache.CaffeineCache#refreshAll
com.coy.l2cache.cache.CaffeineCache#refresh

4、继续分析，上面两个方法在哪里被调用，如下：

# 该方法没有被调用的地方，所以可以忽略
com.coy.l2cache.cache.CaffeineCache#refreshAll

public class CaffeineCache extends AbstractAdaptingCache implements Level1Cache {
    // 该方法被CacheMessageListener.onMessage方法调用
    @Override
    public void refresh(Object key) {
        if (isLoadingCache()) {
            logger.debug("[CaffeineCache] refresh cache, cacheName={}, key={}", this.getCacheName(), key);
            ((LoadingCache) caffeineCache).refresh(key);
        }
    }
}

5、CacheMessageListene缓存监听器，作用是在集群环境下通过监听方式来保证缓存的一致性。

public class CacheMessageListener implements MessageListener {

    @Override
    public void onMessage(CacheMessage message) {
        try {
            if (this.cacheInstanceId.equalsIgnoreCase(message.getInstanceId())) {
                logger.debug("[CacheMessageListener][SyncCache] instanceId is same no need to deal, message={}", message.toString());
                return;
            }
            logger.info("[CacheMessageListener][SyncCache] instanceId={}, cacheName={}, cacheType={}, optType={}, key={}",
                    message.getInstanceId(), message.getCacheName(), message.getCacheType(), message.getOptType(), message.getKey());

            Level1Cache level1Cache = getLevel1Cache(message);
            if (null == level1Cache) {
                return;
            }
            // 关键在这里
            if (CacheConsts.CACHE_REFRESH.equals(message.getOptType())) {
                level1Cache.refresh(message.getKey());
            } else {
                level1Cache.clearLocalCache(message.getKey());
            }
        } catch (Exception e) {
            logger.error("[CacheMessageListener][SyncCache] error", e);
        }
    }

}

通过上面的代码分析，已经定位到具体的代码，也可以基本判断该OOM问题是该场景下出现的。

6、回过头结合 CacheMessageListener 的日志继续分析

1）所有缓存维度的 refresh 消息日志数量

通过下图可以发现 2020-12-02 17:00 ~ 2020-12-03 23:00 缓存监听器的refresh消息操作日志，有13,916,848,020条（139亿）。这个数量已经非常恐怖啦，说明此处有问题。

在这里插入图片描述

2）单个缓存维度的 refresh 消息日志数量

通过下图可以发现 2020-12-02 17:00 ~ 2020-12-03 23:00 缓存监听器的refresh消息操作日志，cacheName=actDiscountCache 的refresh消息操作日志有12,820,529,131条（128亿）。
这么大的refresh消息量，说明这个缓存维度有问题。

在这里插入图片描述

3）单个key维度的 refresh 消息日志数量

* and CacheMessageListener and refresh and actDiscountCache and 56781
key=56781的refresh操作日志有6,358,694,099条（63亿）

在这里插入图片描述

4）单个key维度的 put 日志数量

* and RedissonRBucketCache and put and actDiscountCache and 56781
key=56781的put NullValue 到redis的操作日志有67,466,579条（0.67亿）

在这里插入图片描述

那么问题来了，为什么会有这么多refresh日志和put日志呢？

1）为什么同一个key有大量的put日志？

压测环境有120个pod，在高并发的情况下，获取同一个key的并发请求被打到这120个pod上，当redis中没有数据时，会从DB加载数据并put到redis中，然后发送一个refresh消息（短时间内可以理解为是重复的refresh消息）。以上就解释了同一个key为什么会有这么多的put日志。

理论上来讲，这种并发加载同一个key的情况，是需要对同一个key来加分布式锁处理的，否则请求会打到下游DB上，导致DB的压力增加，但是由于目前DB是阿里云PolarDB顶配，所以结合实际情况，在不影响用户体验且DB能支撑的情况下不加分布式锁。

2）为什么同一个key有大量的refresh日志？

压测环境有120个pod，每一个put日志会发送一个缓存刷新消息，这个缓存刷新消息会被其他119个pod消费，并执行refresh操作，结合上面的日志分析，可初步算出refresh日志数量=put日志数量(0.67) * 120=8,095,989,480（80亿+）。

从上面的分析可知，并发场景下同一个key存在大量的重复refresh消息。

注：这个值不是那么精准，是一个理论值，实际可能会更多。因为消息处理过程中如果redis缓存过期，那么还是会继续加载继续发送。

总结

通过上面的分析可得知问题关键点如下

1、高并发情况下，在加载同一个key的缓存数据时，会触发发送refresh消息，而每个refresh消息会被其他120个pod消费，所以每个pod都会受到大量重复的refresh消息。

2、在收到大量重复refresh消息时，每个消息都会往caffeine的默认线程池 ForkJoinPool 的无界队列中新增一个任务，而caffeine的refresh()方法是异步执行的，所以在消费速度跟不上生产速度的情况下，会导致队列中堆积大量消息，最终导致OOM，这个也就是这次OOM的根本原因所在。