Export cache, eviction, upstream and transform metrics (closes #85)

New pixa_ metrics, none with labels:
- source cache hits and misses, counted once per variant made or checked;
  a source whose cached file cannot be used is a miss
- cache usage and limit gauges; usage is set each time eviction reads it
- eviction count and bytes, from the size_bytes the deleted row returns
- upstream fetch duration histogram and fetch error counter
- transform duration histogram and an in-progress gauge, both including
  the wait for a processing slot

Removing a damaged file during reconciliation is not counted as an
eviction. README lists every metric; the metrics config comment now says
the pixa_ metrics are measured whether or not /metrics is served.

Model: opus-5-5

README.md

@@ -1174,7 +1174,7 @@ Each item below is one setting, named by its config key:
     - `pixa_cache_usage_bytes`: the bytes of sources and variants in the cache,
       as eviction last read them; eviction runs after each store and every five
       minutes
-    - `pixa_cache_max_bytes`: the cache size limit, `cache_max_bytes`
+    - `pixa_cache_max_bytes`: the disk cache limit, `cache_max_bytes`
     - `pixa_cache_evictions_total`: sources and variants removed by eviction
     - `pixa_cache_evicted_bytes_total`: the bytes those evictions freed
     - `pixa_upstream_fetches_total`: fetches of a source image that read any

internal/imageproxy/imageproxy.go

@@ -366,8 +366,10 @@ func (p *Proxy) loadCachedSource(
 }
 
 // processFromSourceOrFetch makes the variant req asks for, from the cached
-// source when there is one and from a fetched source otherwise. It counts
-// whether the source was in the cache.
+// source when there is one and from a fetched source otherwise. It counts a
+// source cache miss when it fetches the source because the source has no row
+// in the cache or its cached file cannot be used, and a source cache hit
+// otherwise.
 //
 // A cached source last checked with upstream CacheTTL or more ago is checked
 // first: upstream is asked to send it only if it changed since. When it
@@ -393,8 +395,6 @@ func (p *Proxy) processFromSourceOrFetch(
 		return p.fetchAndProcess(ctx, req, cacheKey)
 	}
 
-	p.cache.IncrementSourceStats(true)
-
 	if p.cache.Stale(cached.CheckedAt) {
 		fetched, err := p.fetchSource(ctx, req, cached.ETag, cached.LastModified)
 
@@ -405,16 +405,21 @@ func (p *Proxy) processFromSourceOrFetch(
 		case err != nil:
 			p.recordFailedCheck(ctx, req, err)
 		default:
+			p.cache.IncrementSourceStats(true)
+
 			return p.processFetched(ctx, req, cacheKey, fetched)
 		}
 	}
 
 	variant := p.renewVariant(ctx, cacheKey, cached)
 	if variant != nil {
+		p.cache.IncrementSourceStats(true)
+
 		return variant, nil
 	}
 
 	source, sourceSize, sourceFormat := p.loadCachedSource(ctx, req.Source)
+	p.cache.IncrementSourceStats(source != nil)
 
 	// Fetch from upstream if we don't have source data or it's empty
 	if source == nil {

internal/imageproxy/metrics_internal_test.go

@@ -1,14 +1,17 @@
 package imageproxy
 
 import (
+	"os"
 	"testing"
+	"time"
 
+	"sneak.berlin/go/pixa/internal/imageprocessor"
 	"sneak.berlin/go/pixa/internal/imagerequest"
 )
 
-// metricValues holds the metrics of a proxy and its cache that
-// TestProxy_Get_CountsSourceCacheFetchesAndTransforms checks. A histogram
-// is given by its count of observations.
+// metricValues holds the source cache, upstream fetch and transform metrics
+// of a proxy and its cache. A histogram is given by its count of
+// observations.
 type metricValues struct {
 	sourceCacheHits   uint64
 	sourceCacheMisses uint64
@@ -110,3 +113,101 @@ func TestProxy_Get_CountsSourceCacheFetchesAndTransforms(t *testing.T) {
 		}
 	}
 }
+
+// TestProxy_Get_CountsMissingSourceFileAsSourceCacheMiss deletes the file of
+// a cached source but keeps its row. A request for a second variant of that
+// source must fetch the source again, and count a source cache miss, not a
+// hit.
+func TestProxy_Get_CountsMissingSourceFileAsSourceCacheMiss(t *testing.T) {
+	t.Parallel()
+
+	svc, fixtures := setupTestProxy(t)
+
+	// A first request caches the photo as a source.
+	resp, err := svc.Get(t.Context(), widthOnlyRequest(fixtures, 50))
+	if err != nil {
+		t.Fatalf("first Get() error = %v", err)
+	}
+
+	_ = resp.Content.Close()
+
+	source := widthOnlyRequest(fixtures, 50).Source
+
+	err = os.Remove(sourceFilePath(svc, source.Key()))
+	if err != nil {
+		t.Fatalf("failed to delete the cached source file: %v", err)
+	}
+
+	before := readMetricValues(t, svc)
+
+	resp, err = svc.Get(t.Context(), widthOnlyRequest(fixtures, 25))
+	if err != nil {
+		t.Fatalf("Get() of a second variant error = %v", err)
+	}
+
+	_ = resp.Content.Close()
+
+	after := readMetricValues(t, svc)
+	t.Logf("before the second variant: metrics = %+v; after: %+v", before, after)
+
+	if after.sourceCacheHits != before.sourceCacheHits ||
+		after.sourceCacheMisses != before.sourceCacheMisses+1 {
+		t.Errorf("source cache hits went from %d to %d and misses from %d to %d, "+
+			"want no new hit and one more miss", before.sourceCacheHits,
+			after.sourceCacheHits, before.sourceCacheMisses, after.sourceCacheMisses)
+	}
+}
+
+// TestProxy_Get_CountsTransformWaitingForSlotAsInProgress holds the only
+// processing slot and starts a request that must transform the photo. While
+// the request waits for the slot, pixa_transforms_in_progress must be 1; once
+// the request returns, 0.
+func TestProxy_Get_CountsTransformWaitingForSlotAsInProgress(t *testing.T) {
+	t.Parallel()
+
+	svc, fixtures := setupTestProxy(t)
+	svc.processor = imageprocessor.New(
+		imageprocessor.Params{MaxInputBytes: 50 << 20, MaxConcurrentProcessing: 1},
+	)
+
+	release := holdProcessingSlot(t, svc.processor)
+
+	result := startGet(t.Context(), svc, widthOnlyRequest(fixtures, 50))
+
+	// The request fetches the photo first, then waits for the slot.
+	deadline := time.Now().Add(5 * time.Second)
+	for readMetricValues(t, svc).inProgress != 1 && time.Now().Before(deadline) {
+		time.Sleep(10 * time.Millisecond)
+	}
+
+	waiting := readMetricValues(t, svc).inProgress
+	t.Logf("while the request waits for the slot: transforms in progress = %v",
+		waiting)
+
+	select {
+	case got := <-result:
+		t.Fatalf("Get() returned while the only processing slot was held, "+
+			"error = %v", got.err)
+	default:
+	}
+
+	if waiting != 1 {
+		t.Fatalf("transforms in progress = %v while the request waits for the "+
+			"slot, want 1", waiting)
+	}
+
+	release()
+
+	got := <-result
+	if got.err != nil {
+		t.Fatalf("Get() error = %v", got.err)
+	}
+
+	returned := readMetricValues(t, svc).inProgress
+	t.Logf("once the request returned: transforms in progress = %v", returned)
+
+	if returned != 0 {
+		t.Errorf("transforms in progress = %v once the request returned, want 0",
+			returned)
+	}
+}

internal/imgcache/metrics.go

@@ -33,7 +33,7 @@ func (c *Cache) registerMetrics(metricsRegistry prometheus.Registerer) error {
 	})
 	c.maxBytes = prometheus.NewGauge(prometheus.GaugeOpts{
 		Name: "pixa_cache_max_bytes",
-		Help: "The cache size limit in bytes, cache_max_bytes.",
+		Help: "The disk cache limit in bytes, cache_max_bytes.",
 	})
 	c.evictions = prometheus.NewCounter(prometheus.CounterOpts{
 		Name: "pixa_cache_evictions_total",