From 3c629133c2ceecc67c29fc94e28a74433e1d1b16 Mon Sep 17 00:00:00 2001 From: Ethereal49 Date: Fri, 9 Oct 2026 02:48:29 +0800 Subject: [PATCH] usage: refresh caches after same-tick log rewrites (#1328) * usage: same-tick rewrites refresh cached totals and request pages Trust change stamps only when they were settled at the snapshot read's start. Fingerprint recent snapshots and append prefixes, and discard fingerprint trust when the content changes during a read. Fixes https://github.com/yetone/magpie/issues/1305 Verified: deterministic old-predicate FAIL/new PASS; usage tests with race; nogui vet; Linux nogui and Windows builds; usage test cross-compilation for Windows, Darwin and the unsupported-stamp fallback on FreeBSD. Full nogui suite exposed the independent sessions TestList empty-session limit failure. Native Linux GUI vet/build lack pkg-config and GTK/WebKit; native Windows/NTFS execution was not run. * usage: keep FILETIME stamp ages valid beyond UnixNano range Convert whole seconds and the 100ns fraction separately. Checked the epoch, current dates with fractional ticks and year 2500; Windows build and usage test cross-compilation pass. Native Windows execution was not run. * usage: keep history cached after an append settles An unchanged log now validates a recent snapshot's nonempty fingerprint before publishing a settled clone. Preserve its version and sealed blocks so the summary and page caches stay warm without mutating readers' snapshots. Follow-up to the review on https://github.com/yetone/magpie/pull/1328, for https://github.com/yetone/magpie/issues/1305. On e28e686, the real-clock append/read/settle/read tests fail with a version bump and 32,428 additional allocations over 4,000 versus 10 rows. With this change the targeted race run passes, with 165 extra allocations. The existing performance test now measures this path on the real clock. Verification uses Go 1.26.8, a temporary HOME and pinned Go caches. Native Linux GUI checks require missing pkg-config/GTK/WebKit libraries; native Windows/NTFS execution is not available. No GUI assets change. Implementation and verification used AI assistance. Final checks: usage race PASS (421 test results); nogui suite PASS (7,273 test results, 44 packages; 21 skipped tests, 3 packages without tests). Nogui vet, Linux nogui build, Windows build, and usage test cross-compilation for Windows amd64, Darwin arm64 and FreeBSD amd64 PASS. Native Linux GUI vet/build were attempted and failed at the missing pkg-config executable. --- internal/usage/cache_bounds_test.go | 131 ++++++++++++++++++++++ internal/usage/incremental_log_test.go | 60 ++++++++-- internal/usage/log_change_darwin.go | 10 +- internal/usage/log_change_linux.go | 10 +- internal/usage/log_change_other.go | 7 +- internal/usage/log_change_windows.go | 13 ++- internal/usage/log_change_windows_test.go | 6 + internal/usage/log_file.go | 18 ++- internal/usage/log_file_test.go | 2 +- internal/usage/log_index.go | 48 ++++++-- internal/usage/priced_blocks_test.go | 2 + 11 files changed, 271 insertions(+), 36 deletions(-) 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())