Why does Spring execute @Cacheable keyGenerator 2 times for a single invocation of @Cacheable annotated method

Question

Why does Spring execute my custom @Cacheable keyGenerator twice for a single invocation of a method annotated @Cacheable, why not do it just once.

My KeyGenerator implementation

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();
    }
}

My Method annotated with @Cacheable with custom 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 which invokes the method annotated with @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));
    }
}

When I make a single invocation of the method annotated with @Cacheable with my custom keyGenerator, I see 2 executions in my log and dubugger of System.out.println("Generating a key");

Curl to trigger method call invocation

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 have the following setting in application properties to enable tracing of the cache

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'

Conceptually, I would have thought Spring would need to run the keyGenerator only once, use it firstly to lookup the cache, and if not found, when the method is complete, use that same key to put to the cache. So I don't understand why I see this running twice.

My issues with this:

1. I am confused with how it works and why
2. The logging and debugging become confusing
3. Potential performance impact, even though keyGeneration implementation should be cheap, why do it multiple times.

Answer 1

I think I know why, key is generated once for lookup in cache, and once for putting into the cache. Not sure why it works that way, but appears to be what is happening.