Serve a cache hit with no database read or write (closes #309)

A hit opens the variant file and nothing else: its content type comes
from the file's first bytes, and a file in no output format is a miss.
Its access time and count, and the access time of a cached source a
miss uses, go without waiting to one background goroutine that writes
them once a second; each kind of access time waits in a channel of
10,000 that drops the rest. Expired negative cache rows are left to
CleanExpired. The .meta files, metaCache, Lookup and golang-lru go,
with their tests; the two reconciliation walks, identical without the
.meta skip, share one. make bench runs a parallel cache hit benchmark
on the host, outside make check.

Model: opus-5-5

internal/imgcache/pendingcounts_internal_test.go

@@ -1,9 +1,12 @@
 package imgcache
 
 import (
+	"bytes"
 	"context"
 	"database/sql"
 	"errors"
+	"log/slog"
+	"strings"
 	"testing"
 	"time"
 
@@ -73,6 +76,35 @@ func waitForCounters(t *testing.T, cache *Cache, want cacheStatsCounters) {
 	}
 }
 
+// waitForPendingCountsWritten starts the goroutine that writes cache's
+// pending counts, unless it is running, and waits until it has written them
+// all, so that the database holds every count made so far. The goroutine is
+// stopped when the test ends. The database is limited to one connection
+// first: each connection to an in-memory SQLite database opens a new, empty
+// one, so the goroutine must share the connection that holds the schema.
+func waitForPendingCountsWritten(t *testing.T, cache *Cache) {
+	t.Helper()
+
+	if cache.pendingCountsCancel == nil {
+		cache.db.SetMaxOpenConns(1)
+		cache.StartPendingCountWrites()
+
+		t.Cleanup(func() { _ = cache.StopPendingCountWrites(context.Background()) })
+	}
+
+	deadline := time.Now().Add(pendingCountsWait)
+
+	for cache.pendingHits.Load()+cache.pendingMisses.Load()+
+		cache.pendingUpstreamFetches.Load()+cache.pendingUpstreamFetchBytes.Load()+
+		cache.pendingTransforms.Load() > 0 {
+		if time.Now().After(deadline) {
+			t.Fatal("the pending counts were not written")
+		}
+
+		time.Sleep(10 * time.Millisecond)
+	}
+}
+
 // TestService_Get_ReturnsByItsDeadlineWhileTheDatabaseIsBusy holds the
 // database's one connection while a request whose fetch is held reaches its
 // deadline. The request must return with the deadline's error while the
@@ -123,11 +155,12 @@ func TestService_Get_ReturnsByItsDeadlineWhileTheDatabaseIsBusy(t *testing.T) {
 	waitForCounters(t, svc.cache, cacheStatsCounters{missCount: 1})
 }
 
-// TestIncrementStats_ManyCountsPastTheirDeadlineLeaveOneWriteWaiting holds the
-// database's one connection while many misses are counted past their
-// deadline. At most one write may then wait for the connection, and every
-// miss must reach the database once it is free.
-func TestIncrementStats_ManyCountsPastTheirDeadlineLeaveOneWriteWaiting(t *testing.T) {
+// TestIncrementStats_ManyCountsLeaveOneWriteWaiting holds the database's one
+// connection while many misses are added to the pending counts, which the
+// goroutine StartPendingCountWrites starts writes to the database. At most one
+// write may then wait for the connection, and every miss must reach the
+// database once it is free.
+func TestIncrementStats_ManyCountsLeaveOneWriteWaiting(t *testing.T) {
 	t.Parallel()
 
 	cache, _ := newEvictionTestCache(t, 1<<30)
@@ -140,14 +173,10 @@ func TestIncrementStats_ManyCountsPastTheirDeadlineLeaveOneWriteWaiting(t *testi
 
 	waitsBefore := cache.db.Stats().WaitCount
 
-	// Writes given a context past its deadline fail at once.
-	ended, cancel := context.WithDeadline(t.Context(), time.Now())
-	defer cancel()
-
 	const misses = 20
 
 	for range misses {
-		cache.IncrementStats(ended, false, 0)
+		cache.IncrementStats(false, 0)
 	}
 
 	// Once one write waits for the connection, any others start waiting too.
@@ -166,9 +195,9 @@ func TestIncrementStats_ManyCountsPastTheirDeadlineLeaveOneWriteWaiting(t *testi
 	waitForCounters(t, cache, cacheStatsCounters{missCount: misses})
 }
 
-// TestStats_IncludesPendingCounts counts hits and misses whose writes miss
-// their deadline, and checks that Stats adds them to the database's counts
-// before they are written.
+// TestStats_IncludesPendingCounts adds hits and misses to the pending counts,
+// with no goroutine started to write them, and checks that Stats adds them to
+// the database's counts before they are written.
 func TestStats_IncludesPendingCounts(t *testing.T) {
 	t.Parallel()
 
@@ -180,13 +209,9 @@ func TestStats_IncludesPendingCounts(t *testing.T) {
 		t.Fatal(err)
 	}
 
-	// Writes given a context past its deadline fail at once.
-	ended, cancel := context.WithDeadline(t.Context(), time.Now())
-	defer cancel()
-
-	cache.IncrementStats(ended, true, 0)
-	cache.IncrementStats(ended, true, 0)
-	cache.IncrementStats(ended, false, 0)
+	cache.IncrementStats(true, 0)
+	cache.IncrementStats(true, 0)
+	cache.IncrementStats(false, 0)
 
 	stats, err := cache.Stats(t.Context())
 	if err != nil {
@@ -222,19 +247,15 @@ func TestStopPendingCountWrites_WritesPendingCounts(t *testing.T) {
 
 	waitsBefore := cache.db.Stats().WaitCount
 
-	// Writes given a context past its deadline fail at once.
-	ended, cancel := context.WithDeadline(t.Context(), time.Now())
-	defer cancel()
-
-	cache.IncrementStats(ended, true, 0)
+	cache.IncrementStats(true, 0)
 
 	// The goroutine's write waits for the connection.
 	waitForConnectionWaits(t, cache.db, waitsBefore+1)
 
 	// Counted after that write read the pending counts
-	cache.IncrementStats(ended, false, 0)
-	cache.IncrementUpstreamFetch(ended, 1024)
-	cache.IncrementTransformCount(ended)
+	cache.IncrementStats(false, 0)
+	cache.IncrementUpstreamFetch(1024)
+	cache.IncrementTransformCount()
 
 	// The goroutine is told to finish here as well as by the stop, so that it
 	// is told before its write under way ends, however late the stop runs.
@@ -295,11 +316,7 @@ func TestStopPendingCountWrites_ReturnsWhenItsContextEnds(t *testing.T) {
 
 	waitsBefore := cache.db.Stats().WaitCount
 
-	// Writes given a context past its deadline fail at once.
-	ended, cancel := context.WithDeadline(t.Context(), time.Now())
-	defer cancel()
-
-	cache.IncrementStats(ended, true, 0)
+	cache.IncrementStats(true, 0)
 
 	// The goroutine's write waits for the connection.
 	waitForConnectionWaits(t, cache.db, waitsBefore+1)
@@ -327,3 +344,88 @@ func TestStopPendingCountWrites_ReturnsWhenItsContextEnds(t *testing.T) {
 
 	waitForCounters(t, cache, cacheStatsCounters{hitCount: 1})
 }
+
+// TestLookupSource_HandsAccessTimeToTheBackgroundWriter finds a cached source
+// whose access time is an hour old. LookupSource must not write the access
+// time itself but hand it over to be written, and StopPendingCountWrites must
+// then write it.
+func TestLookupSource_HandsAccessTimeToTheBackgroundWriter(t *testing.T) {
+	t.Parallel()
+
+	cache, _ := newEvictionTestCache(t, 1<<30)
+	key := storeEvictionTestSource(t, cache, "example.com", "/photo.jpg",
+		[]byte("source bytes"))
+	anHourAgo := time.Now().Add(-time.Hour)
+	setSourceLastAccessed(t, cache, key, anHourAgo)
+
+	touchedQuery := `
+		SELECT COUNT(*) FROM source_content
+		WHERE source_key = ? AND last_accessed_at > ?
+	`
+	anHourAgoInDatabase := anHourAgo.UTC().Format(sqliteTimestampFormat)
+
+	found, _, err := cache.LookupSource(t.Context(), &imagerequest.Request{
+		Source: imagerequest.Source{Host: "example.com", Path: "/photo.jpg"},
+	})
+	if err != nil || found != key {
+		t.Fatalf("LookupSource() = %q, %v; want %q", found, err, key)
+	}
+
+	if countRows(t, cache, touchedQuery, string(key), anHourAgoInDatabase) != 0 {
+		t.Error("LookupSource wrote the source's access time itself")
+	}
+
+	if waiting := len(cache.pendingSourceAccessTimes); waiting != 1 {
+		t.Errorf("%d access times of sources wait to be written, want 1", waiting)
+	}
+
+	err = cache.StopPendingCountWrites(t.Context())
+	if err != nil {
+		t.Fatalf("StopPendingCountWrites() error = %v", err)
+	}
+
+	if countRows(t, cache, touchedQuery, string(key), anHourAgoInDatabase) != 1 {
+		t.Error("the source's access time was not written")
+	}
+}
+
+// TestStopPendingCountWrites_LogsWhatWasNotWritten makes the write of the
+// access times fail at shutdown, by dropping the table they are written to,
+// while a hit count is written. The stop must return an error and log that
+// access times were not written, and must not log the counts as not written.
+func TestStopPendingCountWrites_LogsWhatWasNotWritten(t *testing.T) {
+	t.Parallel()
+
+	cache, _ := newEvictionTestCache(t, 1<<30)
+
+	var logs bytes.Buffer
+
+	cache.log = slog.New(slog.NewJSONHandler(&logs, nil))
+
+	cache.touchVariant(testVariantKeyOne)
+	cache.IncrementStats(true, 0)
+
+	_, err := cache.db.ExecContext(t.Context(), `DROP TABLE variant_content`)
+	if err != nil {
+		t.Fatalf("dropping variant_content: %v", err)
+	}
+
+	err = cache.StopPendingCountWrites(t.Context())
+	t.Logf("StopPendingCountWrites() error = %v; logged:\n%s", err, logs.String())
+
+	if err == nil {
+		t.Error("StopPendingCountWrites() error = nil, want the access times' error")
+	}
+
+	if !strings.Contains(logs.String(), "access times not written at shutdown") {
+		t.Error("the access times not written were not logged")
+	}
+
+	if strings.Contains(logs.String(), "counts not written at shutdown") {
+		t.Error("the counts, which were written, were logged as not written")
+	}
+
+	if got := readCacheStatsCounters(t, cache); got.hitCount != 1 {
+		t.Errorf("hit count in the database = %d, want 1", got.hitCount)
+	}
+}