Caffeine: Independently track load and refresh duration statistics

[Stephan202]

(Apologies if this feature has been requested before; I searched but did not find anything like it.)

Some context: we implemented a Spring Reactor-based CacheLoader which batches refresh requests, analogous to the CoalescingBulkloader introduced in #316. We're also tracking cache statistics using Micrometer.

The issue: the cache's reported average load time is way higher than expected (_much_ greater than the average duration of the backing HTTP requests). After some head scratching the culprit became clear: we're delaying refresh operations in order to be able to batch them, so the refresh operations skew the statistics.

The feature request: would it be possible for StatsCounter#recordLoadSuccess(loadTime) and StatsCounter#recordLoadFailure(loadTime) to be split out into "load" and "refresh" variants? This would allow users to distinguish the load times that truly matter (i.e. those that make callers wait) from those that matter less and/or are processed with a lower QoS, such as in our bulk refresh case.

[ben-manes]

Thanks, this is an interesting observation. A few questions to dig into how we should approach this.

1. 
   This is a bit quirky because the stats captures the time of a load or reload. In addition to refresh, this includes the compute methods. For example a computeIfPresent that returns null is equivalent to a refresh(key) that returns null, both of which remove the entry. Currently all of this time to calculate the new value is under the load umbrella. Similarly, the time to bulk load is considered a single load, as loadCount is per computation and not per-entry.

Where would you expect a present computation to be recorded? This may be a user-facing penalty. I believe your ask is that you want to separate not by first load and subsequent reloads, but by if it is user-facing versus side-loaded. Thus load would include reloads, but we'd try to represent how much impacts your QoS (as you say, load verse refresh).

1. AsyncLoadingCache#refresh may simply delegate to get(key) when the entry is absent. This is because it can store the future directly into the cache, so a subsequent explicit get(key) could piggyback on the refresh future. Otherwise the explicit load would be required, and the refresh would complete and be abandoned. To split the stats, where would this cost be recorded and would this optimization have to be dropped?

2. Should this be a core statistic or a custom one? It could be captured in application code and adjustments made during reporting. The core stats are the most common and obvious ones, while applications might enrich them with more depth as appropriate. For example some might record the number of explicit removals, where the core only captures automatic ones via eviction. The answer here might be that your team's case is valid but beyond the scope of what the common stats should account for.

[ben-manes]

fyi, I plan on releasing v3 in a week or so as it is otherwise code complete. This is now in a baking period in case of any feedback, e.g. if there is a negative reaction to deprecating CacheWriter in the newly released 2.9 (for removal in 3.0).

If your change would require a major release then we should work out the right solution soon. I am leaning towards (3) which would mean no changes, but we can dig into it this you disagree.

[Stephan202]

@ben-manes sorry for not responding until now. I did start to write an answer (mostly to organize my thoughts on the matter), but "no egg was laid". Hope to find time soon for a proper response (busy day job...). But indeed, so far I have not formulated an argument against (3). Stay tuned :)

[Stephan202]

Again, sorry for the delay.

So I tried to summarize the concerns as follows:

1. With respect to the "type" of an operation there are (at least) two perspectives one can take:
   
   
   
   1. _Load_ vs. _refresh_ operations.
   
   
   2. _Caller waits_ vs. _caller doesn't wait_ operations.
   
   
2. These perspectives are distinct, because some _refresh_ operations (e.g. #computeIfPresent) are in the _caller waits_ category.
3. In some cases a _refresh_/_caller doesn't wait_ operation turns into a _load_/_caller waits_ operation; this happens when a AsyncLoadingCache#refresh is followed by an explicit #get.
4. One may wish to view the recorded durations through two lenses: _per key_ vs. _per cache method invocation_. Currently Caffeine caters to the latter.

Some thoughts on the above:

• For (1) I suspect that users will be more interested in the _caller waits_ vs. _caller doesn't wait_ distinction. After all, one generally uses a cache for the benefit of the caller. But this is not true in general: one can also use a cache to "protect" a backing resource.
• For (3) I suppose one could say that _load_/_caller waits_ timings are more "relevant" than _refresh_/_caller doesn't wait_ timings, so in order to avoid double book keeping ideally one identifies the "cut-over point". But I'd not be surprised if that were prohibitive from an implementation point of view.
• IIUC for (at least?) an async cache a "hit" doesn't mean that the caller doesn't have to wait, since the returned Future may not have completed yet.

So yeah, all this is pretty tough, from an API design perspective :sweat_smile:. At this time I struggle to give concrete advice on how to increase the utility of the recorded stats. If time allows I'll see how we can "instrument around it"; then perhaps it'll be clearer which "core" metrics (if any) really can't be tracked another way.

[ben-manes]

Thanks for the thoughtful response. I like your breakdown, and agree with the wait / no-wait distinction. Of course someone might argue that an async cache should be recorded into no-wait stats as a get is non-blocking, but that depends on the caller's usage making a distinction in the stats unclear.

When we get into advanced scenarios I kind of feel that it is better to give up at the library level, recognize that the user knows best, and hope to give them the tools to do it themselves without too much pain. If we can offer the needed flexibility in a straightforward manner, while not making the common cases confusing, then I think we strike a good balance. That's why most of my efforts have been to increase flexibility (e.g. custom expiration) or improve implementation details that are out-of-scope for a user to consider (e.g. eviction algorithm).

You bring up an excellent point about the AsyncCache and its naive hit rate approach. The current behavior was the simplest and, given the complexities to bootstrap the library, I didn't put much effort into considering alternatives. The problem with recording the stats based on the result of the future is that every get needs to maintain the key's call count somewhere. If we do this via a whenComplete dependent then we allocate on read, which adds undesirable GC pressure. If we store it in a secondary multiset (e.g. Map<CompletableFuture, AtomicInteger>) then we have to manage its concurrent state (ideally w/o allocating a lambda via a compute). If we store an atomic counter on the cache entry then we have to allocate a field and drill into the implementation somehow to increment or read it. It all becomes convoluted for very little value, whereas a user who knows best can manually capture the metrics they deem most accurate for their use-case.

I guess in summary, the line to draw is whether you can instrument around it and how painful that is. For minor annoyances then if we should only improve the library if it is similarly trivial to do so. If extremely frustrating or undoable then we should try to address the feature gap. Otherwise it's acceptable loss and we apologize for the won't do.

[ben-manes]

I'm going to close this for the time being. If your analysis determines that we can and should do something, please reopen. For now I'm going to assume there is nothing actionable, and prepare for v3's release.

[Stephan202]

Thanks for putting the original feature request into perspective. It seems unlikely I'll provide new insights before v3 lands, so fingers crossed :crossed_fingers:.