caffeine loadingCache put“失效”问题排

〇、问题描述

深夜9点，我都准备睡觉了，同事突然找到我，说要问我个问题...
她说她用caffeine(version 2.9.2) put了一个值，但put了个寂寞，得到的仍然是load方法的返回。
她的代码如图:

代码0.jpg
执行结果:
结果0.jpg
且不说这诡异的逻辑，单看代码，我的确没看出问题...
难道caffeine有这么低级的bug？或者是loadingCache不允许显式put?
不行，我不能容忍项目里有此等bug，不找到问题我睡不着。

一、问题复现

按照图片把代码大概写出来，差不多这样...区别是我打印了所有移除事件，原图只打印了过期移除事件

public class CaffeineTest {

    private LoadingCache<Integer, AtomicInteger> errorExceptionCache;

    private void init() {
        errorExceptionCache = Caffeine.newBuilder().expireAfterWrite(3, TimeUnit.SECONDS)
                .removalListener((RemovalListener<Integer, AtomicInteger>)(key, value, cause) -> {
                    System.out.println(cause + ":" + key + "->" + value);
                    if(cause == RemovalCause.EXPIRED) {
                        errorExceptionCache.put(key, new AtomicInteger());
                        System.out.println("in removal listener," + key + "\t" + errorExceptionCache.get(key));
                    }
                }).build(AtomicInteger::new);
    }

    @Test
    public void test() throws InterruptedException {
        this.init();
        System.out.println(1 + "\t" + errorExceptionCache.get(500));
        int value;
        System.out.println(2 + "\t" + (value = errorExceptionCache.get(500).intValue()));
        Assert.assertSame(0, value);
    }
}

运行结果:

1   500
EXPIRED:500->500
REPLACED:500->500
in removal listener,500 0
2   500

二、问题分析

额，一眼看不出问题，掉了不少头发...

1. RemovalListener的执行线程不是主线程，它是一个异步清理线程。所以这些事情发生的顺序，并不是我们一开始想的那样;
2. 主线程sleep 5秒醒来，get(500),而此时RemovalListener清理线程还没把new AtomicInteger()put进去呢（实际上正是get触发了清理任务的执行）。但是，500这个key已经被标记过期了，value不能使用了，只能再次load;
3. 主线程load完，得到500，所以2中打印出来的就是500；
4. RemovalListener中put(500, new AtomicInteger())这个动作，引发了REPLACED事件，把刚才主线程load出的500替换了；
5. 其实最终的缓存值是0，只是没有在合适的时机get一次看看。

三、验证过程代码

    private LoadingCache<Integer, AtomicInteger> errorExceptionCache;

    private void init() {
        errorExceptionCache = Caffeine.newBuilder().expireAfterWrite(3, TimeUnit.SECONDS)
                .removalListener((RemovalListener<Integer, AtomicInteger>)(key, value, cause) -> {
                    System.out.println("in removal listener," + cause + ":" + key + "->" + value);
                    if(cause == RemovalCause.EXPIRED) {
//                        errorExceptionCache.put(key, new AtomicInteger());
//                        errorExceptionCache.refresh(key);
                        Map<Integer, AtomicInteger> map = MapUtil.builder(500, new AtomicInteger())
                                .put(400, new AtomicInteger()).put(300, new AtomicInteger()).build();
                        errorExceptionCache.putAll(map);
                        System.out.println("in removal listener," + key + "\t" + errorExceptionCache.get(key));
                    }
                }).build(key -> {
                    System.out.println("load方法调用: " + key);
                    return new AtomicInteger(key);
                });
    }

    @Test
    public void test() throws InterruptedException {
        this.init();
        System.out.println(1 + "\t" + errorExceptionCache.get(500));
        TimeUnit.SECONDS.sleep(4);
        System.out.println(2 + "\t" + errorExceptionCache.get(500));
        TimeUnit.SECONDS.sleep(1);
        int value;
        System.out.println(3 + "\t" + (value = errorExceptionCache.get(500).intValue()));
        System.out.println(4 + "\t" + errorExceptionCache.get(400));
        Assert.assertSame(0, value);
    }

执行结果:

load方法调用: 500
1   500
load方法调用: 500
in removal listener,EXPIRED:500->500
2   500
in removal listener,REPLACED:500->500
in removal listener,500 0
3   0
4   0

四、后续思考

通过对项目中caffeine现象的观察与阅读部分源码及注释，我大致得出了removalListener的触发机制:

1. removalListener有定时调度机制，但需要在build时设置scheduler，定时调度周期略小于过期时间;
2. 在我的这个例子里，它不是通过定时调度触发的，而是通过实时检查触发的，也就是get前会触发一次清理任务，过期就执行removalListener线程，但get操作本身不会阻塞等待removalListener执行完成。get的串行逻辑很简单，没有或者过期都调用load。