为什么Spring对@Cacheable注解方法的单次调用执行@Cacheable keyGenerator 2次

Question

为什么 Spring 执行我的自定义 @Cacheable keyGenerator 两次以调用注解 @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 Controller 调用带有 @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 注释的方法进行单次调用时，我在我的日志和调试器中看到了 2 次执行 System.out.println("生成密钥");

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

日志 我在应用程序属性中有以下设置以启用缓存跟踪

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. 潜在的性能影响，即使 keyGeneration 实现应该很便宜，为什么要多次执行。

Answer 1

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