diff --git a/internal/usage/cache_bounds_test.go b/internal/usage/cache_bounds_test.go index 36516afa..e07c8122 100644 --- a/internal/usage/cache_bounds_test.go +++ b/internal/usage/cache_bounds_test.go @@ -46,6 +46,136 @@ func TestUsageSameSizeAndMtimeRewrite(t *testing.T) { } } +func TestUsageSameTickRewriteIsNotCached(t *testing.T) { + for _, overBudget := range []bool{false, true} { + for _, appendAfter := range []bool{false, true} { + for _, afterSettle := range []bool{false, true} { + t.Run(fmt.Sprintf("uncached=%t/append=%t/after-settle=%t", overBudget, appendAfter, afterSettle), func(t *testing.T) { + pageHome(t) + if overBudget { + cacheBudget(t, 128) + } + clock := holdClock(t, time.Now()) + tick := time.Now().Truncate(time.Second) + holdLogTick(t, tick) + historyLog(t, 1) + Summarize(All) + QueryPage(All, Filter{}, 0, 100) + warm := logSnapshotFor(true) + if warm.settled || logSnapshotFor(true) != warm { + t.Fatal("unchanged same-tick metadata must reuse its fingerprint without becoming settled") + } + before, err := statLogFile(Path()) + if err != nil { + t.Fatal(err) + } + data, err := os.ReadFile(Path()) + if err != nil { + t.Fatal(err) + } + edited := bytes.Replace(data, []byte(`"in":10`), []byte(`"in":73`), 1) + if bytes.Equal(edited, data) || len(edited) != len(data) { + t.Fatal("fixture must change at the same size") + } + if err := os.WriteFile(Path(), edited, 0600); err != nil { + t.Fatal(err) + } + if err := os.Chtimes(Path(), before.ModTime(), before.ModTime()); err != nil { + t.Fatal(err) + } + after, err := statLogFile(Path()) + if err != nil || !sameLogInfo(before, after) { + t.Fatal("fixture must keep file identity, size, mtime and change stamp", err) + } + if appendAfter { + Append(Record{Time: clock, Agent: "codex", Provider: "relay", Model: "m", Input: 19}) + } + if afterSettle { + logIndexNow = func() time.Time { return tick.Add(time.Hour) } + } + got, want := Summarize(All), summarize(All, clock, Load(time.Time{})) + if got.Totals != want.Totals { + t.Errorf("same-tick summary stale: got %+v want %+v", got.Totals, want.Totals) + } + equalPage(t, QueryPage(All, Filter{}, 0, 100), pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{}))) + logIndexNow = func() time.Time { return tick.Add(time.Hour) } + logSnapshotFor(true) // An oversized read publishes a metadata-only copy. + stable := logSnapshotFor(true) + for range 3 { + if logSnapshotFor(true) != stable { + t.Fatal("settled unchanged metadata was not cached") + } + } + }) + } + } + } +} + +func holdLogTick(t *testing.T, tick time.Time) { + t.Helper() + changeTime, now := logChangeTime, logIndexNow + logChangeTime = func(info os.FileInfo) time.Time { + if info == nil { + return time.Time{} + } + return tick + } + logIndexNow = func() time.Time { return tick.Add(10 * time.Millisecond) } + t.Cleanup(func() { logChangeTime, logIndexNow = changeTime, now }) +} + +func TestUsageRewriteBeforeFingerprintIsNotCached(t *testing.T) { + for _, rewriteAt := range []int{1, 2} { + t.Run(fmt.Sprint("hash=", rewriteAt), func(t *testing.T) { + pageHome(t) + now := holdClock(t, time.Now()) + tick := time.Now().Truncate(time.Second) + holdLogTick(t, tick) + logIndexNow = func() time.Time { return tick.Add(time.Hour) } + historyLog(t, 1) + info, err := statLogFile(Path()) + if err != nil { + t.Fatal(err) + } + data, err := os.ReadFile(Path()) + if err != nil { + t.Fatal(err) + } + edited := bytes.Replace(data, []byte(`"in":10`), []byte(`"in":73`), 1) + if bytes.Equal(edited, data) || len(edited) != len(data) { + t.Fatal("fixture must change at the same size") + } + hash := logRecordHash + hashCalls := 0 + rewritten := false + logRecordHash = func(path string, n int64) string { + hashCalls++ + if hashCalls == rewriteAt { + rewritten = true + if err := os.WriteFile(path, edited, 0600); err != nil { + t.Fatal(err) + } + if err := os.Chtimes(path, info.ModTime(), info.ModTime()); err != nil { + t.Fatal(err) + } + } + return hash(path, n) + } + t.Cleanup(func() { logRecordHash = hash }) + Summarize(All) + if !rewritten { + t.Fatal("fixture did not rewrite at the read boundary") + } + got, want := Summarize(All), summarize(All, now, Load(time.Time{})) + if got.Totals != want.Totals { + t.Fatalf("post-read fingerprint hid a rewrite: got %+v want %+v", got.Totals, want.Totals) + } + equalPage(t, QueryPage(All, Filter{}, 0, 100), pageFromLedger(All, Filter{}, 0, 100, LedgerOf(All, Filter{}))) + }) + } +} + func cacheBudget(t *testing.T, n int64) { t.Helper() old := requestCacheBytes @@ -130,6 +260,7 @@ func TestUsageLargeSummaryIsCompleteButNotCached(t *testing.T) { // page key. The preceding query must leave an initialized page map to write. func TestUsagePageCacheAfterUncachedQuery(t *testing.T) { pageHome(t) + settleLogClock(t) holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) historyLog(t, 1034) normalBudget := requestCacheBytes diff --git a/internal/usage/incremental_log_test.go b/internal/usage/incremental_log_test.go index e4260c64..0b1d6a73 100644 --- a/internal/usage/incremental_log_test.go +++ b/internal/usage/incremental_log_test.go @@ -39,20 +39,40 @@ func historyLog(t testing.TB, n int) { } } +// Cache performance tests start after the filesystem's change stamp has settled. +func settleLogClock(t testing.TB) { + t.Helper() + old := logIndexNow + logIndexNow = func() time.Time { return time.Now().Add(2 * logStampSettle) } + t.Cleanup(func() { logIndexNow = old }) +} + func TestUsageOverviewDoesNotReparseHistory(t *testing.T) { - pageHome(t) - holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) - historyLog(t, 4000) - if s := Summarize(Today); s.Calls != 1 { - t.Fatal(s.Calls) + var allocations [2]float64 + for i, n := range []int{10, 4000} { + pageHome(t) + holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) + historyLog(t, n) + if s := Summarize(Today); s.Calls != 1 { + t.Fatal(s.Calls) + } + allocations[i] = testing.AllocsPerRun(2, func() { + Append(Record{Agent: "codex", Provider: "relay", Model: "m", Input: 1, Status: 200}) + Summarize(Today) + time.Sleep(logStampSettle + 20*time.Millisecond) + Summarize(Today) + }) } - if n := testing.AllocsPerRun(2, func() { Summarize(Today) }); n > 1500 { - t.Fatalf("unchanged Today reparsed history: %.0f allocations", n) + // Measure what history adds, excluding the append and two queries' fixed cost. + t.Logf("append + unsettled + settled summary: %.0f allocations over 4000 rows, %.0f over 10", allocations[1], allocations[0]) + if grown := allocations[1] - allocations[0]; grown > 1500 { + t.Fatalf("append then settle reparsed history: %.0f extra allocations", grown) } } func TestUsageViasSkipsOldHistory(t *testing.T) { pageHome(t) + settleLogClock(t) historyLog(t, 4000) since := time.Now().Add(-time.Hour) if v := Vias(since); len(v) != 1 || v["codex|s"][0].Calls != 1 { @@ -115,6 +135,31 @@ func TestLogAppendReusesSealedBlocks(t *testing.T) { } } +func TestLogAppendThenSettleReusesHistory(t *testing.T) { + pageHome(t) + historyLog(t, 4000) + before := readLogSnapshot() + Append(Record{Agent: "codex", Provider: "relay", Model: "m", Input: 1, Status: 200}) + appended := readLogSnapshot() + if logChangeStamp(appended.info) == "" { + t.Skip("filesystem does not expose change time") + } + if appended.settled || appended.hash == "" { + t.Fatal("append must leave a recent snapshot with a fingerprint") + } + if appended.blocks[0] != before.blocks[0] { + t.Fatal("append rebuilt the sealed history") + } + time.Sleep(logStampSettle + 20*time.Millisecond) + settled := readLogSnapshot() + if !settled.settled || settled.version != appended.version || settled.blocks[0] != appended.blocks[0] { + t.Fatalf("unchanged settled read rebuilt history: version %d -> %d", appended.version, settled.version) + } + if appended.settled { + t.Fatal("promotion mutated the published snapshot") + } +} + func TestLogPartialLineAndTruncation(t *testing.T) { pageHome(t) now := holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) @@ -161,6 +206,7 @@ func TestCachedSummaryRemainsCallerOwned(t *testing.T) { } func BenchmarkIncrementalUsage(b *testing.B) { + settleLogClock(b) // benchmark homes are isolated just as pageHome isolates test homes testenv.SetHome(b, b.TempDir()) b.Setenv("XDG_CONFIG_HOME", b.TempDir()) diff --git a/internal/usage/log_change_darwin.go b/internal/usage/log_change_darwin.go index a581b3cd..0e110c49 100644 --- a/internal/usage/log_change_darwin.go +++ b/internal/usage/log_change_darwin.go @@ -1,19 +1,19 @@ package usage import ( - "fmt" "os" "syscall" + "time" ) // ctime changes even when a writer restores the size and modification time. -func logChangeStamp(info os.FileInfo) string { +func nativeLogChangeTime(info os.FileInfo) time.Time { if info == nil { - return "" + return time.Time{} } stat, ok := info.Sys().(*syscall.Stat_t) if !ok { - return "" + return time.Time{} } - return fmt.Sprintf("%d:%d", stat.Ctimespec.Sec, stat.Ctimespec.Nsec) + return time.Unix(stat.Ctimespec.Sec, stat.Ctimespec.Nsec) } diff --git a/internal/usage/log_change_linux.go b/internal/usage/log_change_linux.go index d9a52283..bc345f47 100644 --- a/internal/usage/log_change_linux.go +++ b/internal/usage/log_change_linux.go @@ -1,19 +1,19 @@ package usage import ( - "fmt" "os" "syscall" + "time" ) // ctime changes even when a writer restores the size and modification time. -func logChangeStamp(info os.FileInfo) string { +func nativeLogChangeTime(info os.FileInfo) time.Time { if info == nil { - return "" + return time.Time{} } stat, ok := info.Sys().(*syscall.Stat_t) if !ok { - return "" + return time.Time{} } - return fmt.Sprintf("%d:%d", stat.Ctim.Sec, stat.Ctim.Nsec) + return time.Unix(stat.Ctim.Sec, stat.Ctim.Nsec) } diff --git a/internal/usage/log_change_other.go b/internal/usage/log_change_other.go index e08b6fb9..ea443580 100644 --- a/internal/usage/log_change_other.go +++ b/internal/usage/log_change_other.go @@ -2,8 +2,11 @@ package usage -import "os" +import ( + "os" + "time" +) // FileInfo exposes no portable change time here. Validate the fingerprint // instead, so a same-size rewrite with restored mtime cannot return stale rows. -func logChangeStamp(os.FileInfo) string { return "" } +func nativeLogChangeTime(os.FileInfo) time.Time { return time.Time{} } diff --git a/internal/usage/log_change_windows.go b/internal/usage/log_change_windows.go index 1a7bd53c..db4716aa 100644 --- a/internal/usage/log_change_windows.go +++ b/internal/usage/log_change_windows.go @@ -3,8 +3,8 @@ package usage import ( - "fmt" "os" + "time" "unsafe" "golang.org/x/sys/windows" @@ -91,15 +91,16 @@ func stampLogHandle(f *os.File, info os.FileInfo) os.FileInfo { if raw.ChangeTime == 0 { return info } - return logFileInfo{FileInfo: info, stamp: fmt.Sprint(raw.ChangeTime)} + changed := time.Unix(raw.ChangeTime/10_000_000-11_644_473_600, raw.ChangeTime%10_000_000*100) + return logFileInfo{FileInfo: info, changeTime: changed} } -// logChangeStamp extracts the stamp captured at snapshot time. It never +// nativeLogChangeTime extracts the time captured at snapshot time. It never // re-opens or re-stats the path: an old snapshot must keep its old stamp even // after the log has been rewritten or appended to. -func logChangeStamp(info os.FileInfo) string { +func nativeLogChangeTime(info os.FileInfo) time.Time { if stamped, ok := info.(logFileInfo); ok { - return stamped.stamp + return stamped.changeTime } - return "" + return time.Time{} } diff --git a/internal/usage/log_change_windows_test.go b/internal/usage/log_change_windows_test.go index 7ef87c66..23f1d111 100644 --- a/internal/usage/log_change_windows_test.go +++ b/internal/usage/log_change_windows_test.go @@ -39,6 +39,10 @@ func requireChangeStamp(t *testing.T, path string) string { if stamp == "" { t.Fatal("ChangeTime is available but the snapshot has no stamp") } + want := time.Unix(basic.ChangeTime/10_000_000-11_644_473_600, basic.ChangeTime%10_000_000*100) + if got := logChangeTime(info); !got.Equal(want) { + t.Fatalf("captured ChangeTime %v != FILETIME %v", got, want) + } return stamp } @@ -122,6 +126,7 @@ func TestLogChangeSnapshotStampImmutable(t *testing.T) { func TestLogChangeSnapshotReuseWithoutFingerprint(t *testing.T) { pageHome(t) + settleLogClock(t) historyLog(t, 1034) first := readLogSnapshot() requireChangeStamp(t, Path()) @@ -141,6 +146,7 @@ func TestLogChangeSnapshotReuseWithoutFingerprint(t *testing.T) { func TestLogChangeTrustedAppendReuse(t *testing.T) { pageHome(t) + settleLogClock(t) historyLog(t, 1034) before := readLogSnapshot() requireChangeStamp(t, Path()) diff --git a/internal/usage/log_file.go b/internal/usage/log_file.go index 1b3ede96..9c1a4388 100644 --- a/internal/usage/log_file.go +++ b/internal/usage/log_file.go @@ -1,12 +1,26 @@ package usage -import "os" +import ( + "fmt" + "os" + "time" +) // Keep native file identity alongside a change time captured from the same // handle. os.SameFile requires the original os.FileInfo, not this wrapper. type logFileInfo struct { os.FileInfo - stamp string + changeTime time.Time +} + +var logChangeTime = nativeLogChangeTime + +func logChangeStamp(info os.FileInfo) string { + c := logChangeTime(info) + if c.IsZero() { + return "" + } + return fmt.Sprintf("%d:%d", c.Unix(), c.Nanosecond()) } func sameLogFile(a, b os.FileInfo) bool { diff --git a/internal/usage/log_file_test.go b/internal/usage/log_file_test.go index 1830a96a..89c58d6d 100644 --- a/internal/usage/log_file_test.go +++ b/internal/usage/log_file_test.go @@ -20,7 +20,7 @@ func TestLogFileInfoPreservesIdentity(t *testing.T) { if err != nil { t.Fatal(err) } - wrapped := logFileInfo{FileInfo: first, stamp: "captured"} + wrapped := logFileInfo{FileInfo: first} if !sameLogFile(wrapped, second) || !sameLogFile(second, wrapped) || !sameLogFile(wrapped, logFileInfo{FileInfo: second}) { t.Fatal("wrapped stat lost native file identity") } diff --git a/internal/usage/log_index.go b/internal/usage/log_index.go index 60ca78b1..61555a29 100644 --- a/internal/usage/log_index.go +++ b/internal/usage/log_index.go @@ -14,7 +14,10 @@ import ( "time" ) -const logBlockRows = 512 +const ( + logBlockRows = 512 + logStampSettle = time.Second +) // Raw and priced chunks share the request cache budget. Oversized histories // remain queryable but their raw blocks are rebuilt instead of retained. @@ -22,6 +25,7 @@ const logBlockRows = 512 type logSnapshot struct { bytes int64 uncached bool + settled bool path string info os.FileInfo off int64 @@ -38,6 +42,9 @@ var logIndex struct { version uint64 } +var logIndexNow = time.Now +var logRecordHash = recordHash + // File writes must never wait for a historical index rebuild. var logAppends struct { sync.Mutex @@ -53,11 +60,23 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot { logIndex.Lock() defer logIndex.Unlock() path := Path() + start := logIndexNow() info, err := statLogFile(path) + settled := settledLogStamp(info, start) old := logIndex.snapshot unchanged := old != nil && old.path == path && (err != nil && old.info == nil || err == nil && sameLogInfo(old.info, info)) - if unchanged && info != nil && logChangeStamp(info) == "" { - unchanged = old.hash != "" && recordHash(path, info.Size()) == old.hash + if unchanged && info != nil { + if logChangeStamp(info) == "" || !old.settled { + unchanged = old.hash != "" && logRecordHash(path, info.Size()) == old.hash + if unchanged && settled { + promoted := *old + promoted.info, promoted.settled = info, true + old = &promoted + logIndex.snapshot = old + } + } else { + unchanged = old.settled && settled + } } if unchanged && (!old.uncached || metadataOnly) { return old @@ -66,7 +85,7 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot { logIndex.version++ } - next := &logSnapshot{path: path, info: info, version: logIndex.version, keyProviders: map[string]bool{}} + next := &logSnapshot{path: path, info: info, settled: settled, version: logIndex.version, keyProviders: map[string]bool{}} if err != nil { logIndex.snapshot = next return next @@ -74,8 +93,8 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot { logAppends.Lock() notePath, noteBase, noteLast := logAppends.path, logAppends.base, logAppends.last logAppends.Unlock() - trusted := logChangeStamp(info) != "" && notePath == path && sameLogInfo(oldInfo(old), noteBase) && sameLogInfo(info, noteLast) - continued := old != nil && old.path == path && old.info != nil && sameLogFile(old.info, info) && info.Size() > old.info.Size() && (trusted || old.hash != "" && recordHash(path, old.info.Size()) == old.hash) + trusted := old != nil && old.settled && logChangeStamp(info) != "" && notePath == path && sameLogInfo(oldInfo(old), noteBase) && sameLogInfo(info, noteLast) + continued := old != nil && old.path == path && old.info != nil && sameLogFile(old.info, info) && info.Size() > old.info.Size() && (trusted || old.hash != "" && logRecordHash(path, old.info.Size()) == old.hash) if continued && !old.uncached { next.off, next.first = old.off, old.first next.blocks = slices.Clone(old.blocks) @@ -89,6 +108,9 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot { if _, err = f.Seek(next.off, 0); err != nil { return next } + if !trusted || !settled { + next.hash = logRecordHash(path, info.Size()) + } var tail *rowChunk if n := len(next.blocks); n > 0 && next.blocks[n-1].Count < logBlockRows { tail = next.blocks[n-1].writable() @@ -123,8 +145,10 @@ func logSnapshotFor(metadataOnly bool) *logSnapshot { if tail != nil { next.blocks = append(next.blocks, tail.freeze()) } - if !trusted || logChangeStamp(info) == "" { - next.hash = recordHash(path, info.Size()) + // A rewrite during the read must not give old blocks the new content's hash. + if (!trusted || !settled) && next.hash != logRecordHash(path, info.Size()) { + next.hash = "" + next.settled = false } logAppends.Lock() // Preserve writes which arrived while this immutable snapshot was built. @@ -194,6 +218,14 @@ func oldInfo(s *logSnapshot) os.FileInfo { } return s.info } + +// A read in the change stamp's clock tick cannot prove that a later equal +// stamp still names the same bytes. Decide before reading, not at reuse time. +func settledLogStamp(info os.FileInfo, start time.Time) bool { + c := logChangeTime(info) + return !c.IsZero() && c.Before(start.Add(-logStampSettle)) +} + func sameLogInfo(a, b os.FileInfo) bool { return a != nil && b != nil && sameLogFile(a, b) && a.Size() == b.Size() && a.ModTime().Equal(b.ModTime()) && logChangeStamp(a) == logChangeStamp(b) } diff --git a/internal/usage/priced_blocks_test.go b/internal/usage/priced_blocks_test.go index a0608a3b..d06d5fbb 100644 --- a/internal/usage/priced_blocks_test.go +++ b/internal/usage/priced_blocks_test.go @@ -24,6 +24,7 @@ func appendAndQueryAllocs(t *testing.T, n int) float64 { } func TestRequestPageAppendDoesNotRepriceHistory(t *testing.T) { + settleLogClock(t) holdClock(t, time.Date(2026, 9, 30, 12, 0, 0, 0, time.Local)) // A query costs a fixed number of allocations that depends on the // machine (on Windows, provider sign-in lookups read the environment and @@ -96,6 +97,7 @@ func TestRequestPageInvalidatesLivePrice(t *testing.T) { } func BenchmarkRequestPageAfterAppend(b *testing.B) { + settleLogClock(b) testenv.SetHome(b, b.TempDir()) b.Setenv("XDG_CONFIG_HOME", b.TempDir()) b.Setenv("XDG_CACHE_HOME", b.TempDir())