Instrument @Cacheable for observability

[patpatpat123]

** Enhancements requests **

To Reproduce

Here is the code:

@Configuration
@EnableCaching
public class CacheConfig {

  @Bean
  public CacheManager cacheManager() {
    CaffeineCacheManager cacheManager = new CaffeineCacheManager();
    Cache<Object, Object> cache = Caffeine.newBuilder().recordStats().build();
    cacheManager.registerCustomCache("test", cache);
    return cacheManager;
  }

}

  @GetMapping("/getAnimal")
  public String getAnimal(@RequestParam String name) {
    LOGGER.info("caching " + name);
    String person = getAnimal(name);
    return person;
  }

 @Cacheable("AnimalCash")
  public String getAnimal(String name) {
    //LOG
    System.out.println("please see me only once to prove caching works: " + name);

    //expensice call here, hope cache will work
    ResponseEntity<Map> response = this.restClient.post()
            .uri("http://localhost:8081/returnObject")
            .body(Map.of("name", "azerty"))
            .retrieve()
            .toEntity(Map.class);
    return response.getBody().keySet().toString();
  }

(mock an expensive downstream service)

    @PostMapping("/justString")
    public String justString(@RequestParam String name) {
        System.out.println("please only see me once " + name);
        try {
            Thread.sleep(9000);
        } catch (InterruptedException e) {
            throw new RuntimeException(e);
        }
        return name.toUpperCase() + "test";
    }

As you can see, this is a straightforward piece of code, where there is the use of cacheable to cache an expensive http call.
The code is working, because the second call would get the data directly from the cache (checked there is no more call on the downstream service, the response comes very fast)

Expected behavior

For the traces, while it is technically correct that there is no trace for the network call, since it did not happen.
Can this be enhanced by showing a trace that it went to the cache?

Thank you

[bclozel]

Hello @patpatpat123 and thanks for the detailed report.

For each instrumentation we implemented in Spring Framework, we had the following requirements:

• the instrumentation must measure a meaningful and consistent operation
• the operation should involve I/O operations or significant processing time
• instrumentation should not replace profiling

In this case, I don't think we should instrument @Cacheable operations. This annotation is merely a marker that says the result should be retrieved from a (possibly in-memory) cache. In your case, your application is producing a trace for cache misses, but if the method was doing intensive CPU work and no remote call, you wouldn't get any. The meaning of what is measured always depends on the cache implementation and the method implementation. If a @Cacheable method is taking too long, is it because the remote call is taking long or is it because the cache lookup is slow?

I think in this case, you could annotate the method with @Observed and ensure that:

• what's executed in the cached method is instrumented (here, the HTTP client is instrumented)
• if the cache does I/O (like redis), the client is instrumented as well; if the cache is in-memory, you'll get a short observation but with no trace, as expected

I'll decline this issue for now. Thanks!