CaffeineCache metrics are doubled

[jasonsaruulo]

Describe the bug

Hey Quarkus team,

we are using Quarkus' cache and Micrometer extensions.

• https://quarkus.io/guides/cache
• https://quarkus.io/guides/telemetry-micrometer

We realized that our cache metrics are doubled.

# HELP cache_gets_total The number of times cache lookup methods have returned a cached (hit) or uncached (newly loaded or null) value (miss).
# TYPE cache_gets_total counter
cache_gets_total{cache="users-cache",result="hit",} 0.0
cache_gets_total{cache="users-cache",result="miss",} 2.0 

In the example above, we expected 1 cache miss instead.

We inject the cache, access it as CaffeineCache and use its getIfPresent method.

@Inject
@CacheName(CACHE_NAME)
Cache cache;

cache.as(CaffeineCache.class).getIfPresent(key);

We investigated the issue a bit and think that CaffeineCacheImpl is counting hits/misses while the underlaying AsyncCache is counting as well and both use the same StatsCounter.

https://github.com/quarkusio/quarkus/blob/main/extensions/cache/runtime/src/main/java/io/quarkus/cache/runtime/caffeine/CaffeineCacheImpl.java

Expected behavior

1 cache hit/miss is only reported once in metrics.

Actual behavior

1 cache hit/miss is reported twice in metrics.

How to Reproduce?

No response

Output of uname -a or ver

No response

Output of java -version

21

Quarkus version or git rev

3.9.2

Build tool (ie. output of mvnw --version or gradlew --version)

Gradle 8.6

Additional information

No response

[quarkus-bot]

/cc @ebullient (metrics), @gwenneg (cache), @jmartisk (metrics)

[geoand]

Thanks for reporting!

This indeed seems weird... @gwenneg do you remember why our code is also manually recording stastistics?

[ebullient]

those are not doubles.

cache_gets_total{cache="users-cache",result="hit",} 0.0
cache_gets_total{cache="users-cache",result="miss",} 2.0 

One is hit, and one is miss. Two separate time series because the result value is different.

[geoand]

cache_gets_total{cache="users-cache",result="miss",} 2.0

This is the problem AFAIU - that the miss is double counted not that there are 2 entries

[ebullient]

I totally missed that you meant the value, not the series. 🤦‍♀️

[geoand]

I made the same mistake initially!

[gwenneg]

Thanks for reporting!

This indeed seems weird... @gwenneg do you remember why our code is also manually recording stastistics?

I don't, but I'll take a look at this tomorrow. There's an integration that checks metrics IIRC. This should have been caught, or maybe that test coverage isn't good enough.

[gwenneg]

There is indeed a bug and the integration test didn't cover it. I'll submit a PR to fix both of them shortly.

[gwenneg]

Metrics are manually updated here and it's fine because the Caffeine cache is used as a Map, which prevents Caffeine internal logic about metrics from being executed:

quarkus/extensions/cache/runtime/src/main/java/io/quarkus/cache/runtime/caffeine/CaffeineCacheImpl.java

Lines 165 to 183 in 25dac45

	private <K, V> CompletableFuture<Object> getFromCaffeine(K key, Function<K, V> valueLoader) {
	CompletableFuture<Object> newCacheValue = new CompletableFuture<>();
	CompletableFuture<Object> existingCacheValue = cache.asMap().putIfAbsent(key, newCacheValue);
	if (existingCacheValue == null) {
	statsCounter.recordMisses(1);
	try {
	Object value = valueLoader.apply(key);
	newCacheValue.complete(NullValueConverter.toCacheValue(value));
	} catch (Throwable t) {
	cache.asMap().remove(key, newCacheValue);
	newCacheValue.complete(new CaffeineComputationThrowable(t));
	}
	return unwrapCacheValueOrThrowable(newCacheValue);
	} else {
	LOGGER.tracef("Key [%s] found in cache [%s]", key, cacheInfo.name);
	statsCounter.recordHits(1);
	return unwrapCacheValueOrThrowable(existingCacheValue);
	}
	}

On the other hand, this method (which was added more recently) relies on the Caffeine cache impl including the logic about metrics, so we should have never modified the metrics manually from the extension in that case:

quarkus/extensions/cache/runtime/src/main/java/io/quarkus/cache/runtime/caffeine/CaffeineCacheImpl.java

Lines 126 to 153 in 25dac45

	public <V> CompletableFuture<V> getIfPresent(Object key) {
	Objects.requireNonNull(key, NULL_KEYS_NOT_SUPPORTED_MSG);
	CompletableFuture<Object> existingCacheValue = cache.getIfPresent(key);
	// record metrics, if not null apply casting
	if (existingCacheValue == null) {
	statsCounter.recordMisses(1);
	return null;
	} else {
	LOGGER.tracef("Key [%s] found in cache [%s]", key, cacheInfo.name);
	statsCounter.recordHits(1);
	// cast, but still throw the CacheException in case it fails
	return unwrapCacheValueOrThrowable(existingCacheValue)
	.thenApply(new Function<>() {
	@SuppressWarnings("unchecked")
	@Override
	public V apply(Object value) {
	try {
	return (V) value;
	} catch (ClassCastException e) {
	throw new CacheException("An existing cached value type does not match the requested type", e);
	}
	}
	});
	}
	}