为什么spring对@Cacheable注释方法的一次调用执行@Cacheable keyGenerator两次

Question

为什么spring对一个注释为@Cacheable的方法的一次调用执行我的定制@Cacheable密钥生成器两次，为什么不只执行一次。

我的KeyGenerator实现

package com.example.demo;

import org.springframework.cache.interceptor.KeyGenerator;
import org.springframework.stereotype.Component;

import java.lang.reflect.Method;
import java.util.ArrayList;

/**
 * Custom key generator
 */
@Component(value = "customerKeyGenerator")
public class CustomerKeyGen implements KeyGenerator
{
    @Override
    public Object generate(Object target, Method method, Object... params)
    {
        System.out.println("Generating a key");
        ArrayList<String> customerNames = (ArrayList<String>) params[0];
        return customerNames.hashCode();
    }
}

我的方法用@Cacheable和自定义keyGenerator注释

package com.example.demo;

import org.springframework.cache.annotation.Cacheable;
import org.springframework.stereotype.Component;

import java.util.ArrayList;

@Component
public class CustomerService {

    @Cacheable(value = "customersCache", keyGenerator = "customerKeyGenerator")
    public int getCountOfCustomers(ArrayList<String> customerNames) {
        return customerNames.size();
    }
}

spring Rest控制器，它调用用@cacheable注释的方法

package com.example.demo;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Controller;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.ResponseBody;

import java.util.ArrayList;

@Controller
public class CustomerController {
    @Autowired
    CustomerService customerService;

    @RequestMapping("/")
    @ResponseBody
    String home() {
        return "Hello World!";
    }

    @RequestMapping("/countCustomers")
    @ResponseBody
    String countCustomers() {
        ArrayList<String> customerNames = new ArrayList<>();
        customerNames.add("john");
        customerNames.add("bill");

        return "countOfCustomers=" + String.valueOf(customerService.getCountOfCustomers(customerNames));
    }
}

当我用自定义的keyGenerator对用@Cacheable注释的方法进行一次调用时，我在System.out.println的日志和dubugger中看到2次执行（“生成密钥”）；

Curl以触发方法调用调用

curl http://127.0.0.1:8080/countCustomers
 % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100    18  100    18    0     0     18      0  0:00:01 --:--:--  0:00:01    
76countOfCustomers=2

Log I在应用程序属性中有以下设置来启用对缓存的跟踪

logging.level.org.springframework.cache=trace

...
2018-08-27 11:56:53.753  INFO 18756 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2018-08-27 11:56:53.757  INFO 18756 --- [           main] c.example.demo.TestCacheableApplication  : Started TestCacheableApplication in 3.543 seconds (JVM running for 5.137)
2018-08-27 11:56:58.411  INFO 18756 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring FrameworkServlet 'dispatcherServlet'
2018-08-27 11:56:58.411  INFO 18756 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization started
2018-08-27 11:56:58.446  INFO 18756 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : FrameworkServlet 'dispatcherServlet': initialization completed in 35 ms
Generating a key
2018-08-27 11:56:58.480 TRACE 18756 --- [nio-8080-exec-1] o.s.cache.interceptor.CacheInterceptor   : Computed cache key '104328221' for operation Builder[public int com.example.demo.CustomerService.getCountOfCustomers(java.util.ArrayList)] caches=[customersCache] | key='' | keyGenerator='customerKeyGenerator' | cacheManager='' | cacheResolver='' | condition='' | unless='' | sync='false'
2018-08-27 11:56:58.480 TRACE 18756 --- [nio-8080-exec-1] o.s.cache.interceptor.CacheInterceptor   : No cache entry for key '104328221' in cache(s) [customersCache]
Generating a key
2018-08-27 11:56:58.480 TRACE 18756 --- [nio-8080-exec-1] o.s.cache.interceptor.CacheInterceptor   : Computed cache key '104328221' for operation Builder[public int com.example.demo.CustomerService.getCountOfCustomers(java.util.ArrayList)] caches=[customersCache] | key='' | keyGenerator='customerKeyGenerator' | cacheManager='' | cacheResolver='' | condition='' | unless='' | sync='false'

从概念上讲，我认为spring只需要运行一次keyGenerator，首先使用它查找缓存，如果没有找到，当方法完成时，使用相同的键将其放入缓存。所以我不明白为什么我看到这个跑了两次。

我的问题是：

1. 我对它的工作原理和原因感到困惑
2. 日志记录和调试变得混乱
3. 潜在的性能影响，尽管密钥生成实现应该很便宜，但为什么要多次执行。

Answer 1

我想我知道为什么了，密钥生成一次是为了在缓存中查找，一次是为了放入缓存。不知道为什么会这样，但似乎是正在发生的事情。