bug: hybrid hit/miss duration includes caller-side wait; `try_unwrap()` skips metrics

Summary

foyer_hybrid_op_duration{op="hit"|"miss"} is recorded when the caller's HybridGet / HybridGetOrFetch future completes. The timer starts when the future is created. The lookup itself (memory hit, disk load or outer fetch) runs in a spawned RawFetch task and finishes without being polled by the caller.

So the histogram measures how long the caller took to come back for the result, not how long the cache took. If a caller creates the future, gets Pending, and does other work before awaiting it, that whole interval is recorded as hit or miss latency.

Related inconsistency: try_unwrap() on a ready future (memory hit) returns the entry without recording anything. The same memory hit obtained through .await is counted. Hit counts and the hit-latency distribution therefore depend on how the caller consumes the future.

Code (main @ 3172936)

• start is taken when the future is created:
  • HybridCache::get
  • HybridCache::get_or_fetch
• hybrid_hit_duration / hybrid_miss_duration are recorded as this.start.elapsed() in the caller-facing poll:
  • HybridGet
  • HybridGetOrFetch
• The work is spawned and completes independently of the caller: spawner.spawn(fetch) in RawCache::get_or_fetch_inner.
• try_unwrap() records nothing:
  • HybridGet::try_unwrap
  • HybridGetOrFetch::try_unwrap

By contrast, foyer_storage_op_duration is recorded inside Store::load, on the task that does the work, so it is not affected.

What we saw

Setup: RisingWave on foyer 0.21.2, psync IO engine, block engine. RisingWave uses get_or_fetch for its SST block and meta caches.

Under heavy backpressure, a streaming executor's block fetch is polled once and returns Pending. This happens through the barrier-batching peek. The actor is then blocked for seconds sending downstream before it polls the fetch again.

On one node over a 3-hour window:

Over ~170 hourly samples, hybrid hit latency correlated 0.88 with the application's own stall metric and 0.13 with store-level hit latency. The disk cache was healthy. The hybrid metric made it look slow, and sent us resizing and warming the disk cache before we found this.

The two caches in RisingWave are also not comparable:

• Block lookups call try_unwrap() first. Memory hits never reach the metric, so the block cache "hit" series contains only disk hits (~250/s).
• Meta lookups .await directly, so their "hit" series is dominated by memory hits.

Minimal repro (sketch)

// Any HybridCache; a memory hit is enough.
cache.insert(1, 1);

let fut = cache.get(&1);                          // `start` is taken here
tokio::time::sleep(Duration::from_secs(2)).await; // caller busy elsewhere
let _ = fut.await;                                // ~2 s recorded as a hit

// Same with get_or_fetch(): the spawned RawFetch finishes in ~1 ms,
// but ~2 s is recorded as a hit or miss.

Suggested fix

1. Record hit/miss latency where the work happens. For example, record it when RawFetch completes the optional (disk) or required (outer) fetch, labelled by source. Memory hits only need a counter.
2. If caller-side wait is useful, either:
   • export it as a separate, clearly named histogram, or
   • document that hybrid_op_duration spans from future creation to the caller's completing poll.
3. Count hits returned through try_unwrap(), so hit ratios don't depend on whether callers use try_unwrap() or .await.

Related: #1168 (disk op duration measured the wrong span), #1038 (moving hit/miss metrics to where the work happens).