Issue observed with Spring cache + micrometer + caffeine

[patpatpat123]

Describe the bug
Hello team,

I would like to reach out to report a bug with springboot, spring cache, micrometer and caffeine.

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
Expected behavior 1, for traces:
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?

Expected behavior 2, for metrics:
Since there is a call which "cache miss" and another call which "cache hit", I would expect to see some counter incremented.

However, the line stays flat. May I ask what the value stays at 0, despite having cache miss and cache hit?

Additional context
[Add any other context about the problem here, e.g. related issues.]

https://micrometer-metrics.slack.com/archives/C662HUJC9/p1734628357662449

Environment

  <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>3.4.0</version>
        <relativePath/> <!-- lookup parent from repository -->
    </parent>

 <dependencies>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-cache</artifactId>
        </dependency>

        <dependency>
            <groupId>com.github.ben-manes.caffeine</groupId>
            <artifactId>caffeine</artifactId>
        </dependency>

<dependency>
		<groupId>org.springframework.boot</groupId>
		<artifactId>spring-boot-starter-actuator</artifactId>
	</dependency>
	<dependency>
		<groupId>io.opentelemetry</groupId>
		<artifactId>opentelemetry-exporter-otlp</artifactId>
	</dependency>
	<dependency>
		<groupId>io.micrometer</groupId>
		<artifactId>micrometer-tracing-bridge-otel</artifactId>
	</dependency>

    </dependencies>

[jonatan-ivanov]

Cross posted from: https://micrometer-metrics.slack.com/archives/C662HUJC9/p1734628357662449

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?

There is a trace, I think what you meant is there is no span for cache miss. If so, this is not a Micrometer question I think but probably a Spring Framework issue to instrument @Cacheable.

Also, please look into my answer on Slack, let me copy it to here:
I think there are more ways you can signal that the call went to cache or it did not:

1. Ask instrumentation of @Cacheable in a Spring Framework issue so that you will see a span for getting the data from the cache.
2. In your controller method, get the current observation and set a cached=true keyvalue on it. In your service do the same but set cached=false (it overwrites the previously set value). So if the method of the service will be actually called cached will be false and if it is not called cached will be true:

@GetMapping("/getAnimal")
public String getAnimal(@RequestParam String name) {
    observationRegistry.getCurrent().keyValue("cached", "true");
    return personService.getAnimal(name);
}

@Cacheable("AnimalCache")
public String getAnimal(String name) {
    observationRegistry.getCurrent().keyValue("cached", "false");
    return this.restClient.post()
            ...;
}

You can also create a “getAnimal” observation and do the same on it instead of using the http observation.

Since there is a call which "cache miss" and another call which "cache hit", I would expect to see some counter incremented.
However, the line stays flat. May I ask what the value stays at 0, despite having cache miss and cache hit?

Where is this metric coming from, are you using CaffeineCacheMetrics?

[patpatpat123]

Thank you for the detailed answer @jonatan-ivanov

I created an enhancement request and crossing my fingers.

spring-projects/spring-framework#34219

Regarding the metrics, could you please help elaborate on CaffeineCacheMetrics?

I could come up with four implementations so far.
However, none of them are working (data always shows 0).

Could you please let me know if there are any official ways to configure Caffeine with micrometer metrics?

Try 1: Found io.micrometer.core.instrument.binder.cache.CaffeineStatsCounter; What is this?

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

Try 2: Found https://docs.micrometer.io/micrometer/reference/reference/cache.html

  @Bean
  public CacheManager cacheManager(MeterRegistry registry) {
    CaffeineCacheManager cacheManager = new CaffeineCacheManager();
    Cache<Object, Object> cache = Caffeine.newBuilder().recordStats().build(key -> "");
    List<Tag> expectedTags = List.of(Tag.of("testkey", "testvalue"));
    CaffeineCacheMetrics<Object, Object, Cache<Object, Object>> metrics = new CaffeineCacheMetrics<>(cache, "test", expectedTags);
    CaffeineCacheMetrics.monitor(registry, cache, "test", expectedTags);
    cacheManager.registerCustomCache("test", cache);
    return cacheManager;
  }

Try 3: Found https://stackoverflow.com/questions/74393289/caffeine-cache-metrics-only-report-cache-size-but-not-hit-miss-ratio-with-microm/74683074#74683074

  @Bean
  public CacheManager cacheManager(MeterRegistry registry) {
    CaffeineCacheManager cacheManager = new CaffeineCacheManager() {
      @Override
      protected Cache<Object, Object> createNativeCaffeineCache(String name) {
        return CaffeineCacheMetrics.monitor(registry, super.createNativeCaffeineCache(name), name);
      }
    };
    Cache<Object, Object> cache = Caffeine.newBuilder().recordStats().build();
    cacheManager.registerCustomCache("test", cache);
    return cacheManager;
  }

Try 4:

  @Bean
  public Caffeine<Object, Object> caffeineConfig() {
    return Caffeine.newBuilder().recordStats();
  }

  @Bean
  public CacheManager cacheManager(Caffeine<Object, Object> caffeine, MeterRegistry registry) {
    CaffeineCacheManager cacheManager = new CaffeineCacheManager() {
      @Override
      protected Cache<Object, Object> createNativeCaffeineCache(String name) {
        return CaffeineCacheMetrics.monitor(registry, super.createNativeCaffeineCache(name), name);
      }
    };
    cacheManager.setCaffeine(caffeine);
    cacheManager.setCacheNames(List.of("test"));
    return cacheManager;
  }

[jonatan-ivanov]

You need to call bindTo, see the docs: https://docs.micrometer.io/micrometer/reference/reference/cache.html#cache-caffeine
But doesn't Spring Boot configure this for you out of the box?

[shakuzen]

If you're using Spring Boot, you should refer to their documentation. Namely, this section for metrics and this section for Spring Boot's auto-configuration of Caffeine.

If Caffeine is present, a CaffeineCacheManager (provided by the spring-boot-starter-cache starter) is auto-configured.

You creating your own CaffeineCacheManager bean is probably causing the Spring Boot auto-configuration to back off.