Logging hit / miss

[elab]

I'm using Caffeine via Spring @Cacheable(sync=true) annotation and setting parameters in application.yml (spring.cache.caffeine.*).

I'd like to see in log if the returned value has been retrieved from cache or not. How to achieve that?

The logging settings

org.springframework.cache: trace
com.github.benmanes.caffeine: trace

only produce the output "Computed cache key ..." like

2020-06-11 03:19:54,969 TRACE [http-nio-8080-exec-9] o.s.cache.interceptor.CacheInterceptor   : Computed cache key ... for operation ...

[ben-manes]

I suppose you could supply a custom StatsCounter that logs on the hit/miss methods. You would probably want to collect stats anyway to monitor the hit rates.

[elab]

Unfortunately, a custom StatsCounter is not an easy and satisfying way.

1. There is no existing implementation I could extend. All implementations including the default ConcurrentStatsCounter are final.
2. There is no access to key, cache name, returned value from StatsCounter callback methods.
3. Instead of 2-3 lines in application properties, example:

spring.cache:
  cache-names: <cache1>, <cache2>
  caffeine.spec: maximumSize=1000, expireAfterWrite=300s, recordStats

an additional code has to be written (Cache Configuration, CacheManager bean, StatsCounter implementation...)

Perhaps it could be possible to add hit/miss logging at debug or trace level directly to the cache implementation? I think it would be a very welcome addition for many users.

[ben-manes]

Oh, you're right. It is too limited for this case.

I am hesitant to add logging on the hot paths, as we currently only do so on failure conditions that are may be accidentally swallowed. It would require that we capture and track state just for logging, e.g. concurrency might cause us to print the wrong value if updated, so even when disabled there can be overhead to ensure correct propagation. For stats we don't need to do that since they only need the resulting behavior to increment counters by.

The cache is really just a fancier ConcurrentHashMap, and one does not expect logging inside of a hash table or other data structures. Java Collections, Guava, Apache Commons, and other in-memory caching libraries similarly don't have any internal logging beyond statistics. All leave it up to the application or framework level to who have enough context to make logging valuable. For example we don't have a "cache name" and no CacheManager, so random log statements might be hard to backtrace. All of that is provided by Spring Cache, who who is responsible for the life-cycle in your application.

We do provide a JCache adapter, which has those frameworky concepts. That could be argued to include this richer logging. However JCache is largely a failed standard due to its ugly, often broken, and non-idiomatic API. We offer that for simpler integrations if used by a framework (like Hibernate), but most big vendors offer custom integrations into those frameworks because the jsr is mostly for show rather than actual usage. So I don't think us changing it there and having you switch over would be very useful for you, and expose your app to more quirks.

Given your needs, your best bet is to ask Spring Cache to enhance their generic logging. As you noted, they already include some at trace level under org.springframework.cache so improving this would solve your problem much better than we can in the data structure.

[elab]

Thank you, Ben, for detailed explanation. I understand your point.
I created an issue in the Spring Framework: spring-projects/spring-framework#25248