mirror of
https://gitcode.com/JianFeeeee/ModelRouter.git
synced 2026-09-21 17:38:00 +00:00
perf(gateway): load request logs on demand instead of holding them in memory
Startup RSS on this deployment was 56 MB with a 29 MB audit log and ~10 MB
without one: LoadAudit() json-unmarshalled the ENTIRE file into the aggregates
and kept a 10000-entry ring of raw records. Two more paths had the same shape —
AuditRecords() materialized a whole export window into a []Req before sorting
it, and a dashboard poll serialized the full ring so the browser could render
300 rows of it.
The audit file is now the source of truth and memory only holds the live
window:
* LoadAudit replays only the last auditReplayBytes (4 MB) and drops the
truncated first line; the ring default drops 10000 -> 500, which still
covers both of its consumers (the status page's 5-minute SourceRecent /
SourceAverages windows and the first screen of the records table).
replayPartial is exported so the UI can say the totals cover a window
rather than all time. Token-quota accounting is unaffected: it reads the
modelHour buckets, not the ring (pinned by a test).
* AuditPage(cursor, limit, key) pages records straight off disk, reading the
newest file backwards in 64 KB chunks and returning as soon as the page is
full. The cursor is "<file>:<offset>" and walks into rotated .old files;
a cursor whose file rotated away reports rotated=true so the client can
reset instead of silently skipping records. No state is cached between
requests and the file handle is closed before responding, so "release when
the user leaves the page" is guaranteed by never retaining anything.
* StreamAuditRecords(from,to,key,fn) replaces the accumulate-then-sort export
path; the CSV handler writes rows as they are read and flushes every 1000,
and a write error (client gone) aborts the walk. Export memory is O(1)
regardless of the window. AuditRecords is kept as a test-only wrapper.
* Snapshot ships one screen (firstScreenRecords=100) by default; aggregates
are untouched.
* Audit rotation 64 MB x 10 -> 16 MB x 16: same 256 MB total budget, but a
smaller newest file keeps the first reverse page cheap.
New route: GET /api/stats/records?before=&limit=&key= (non-admins are pinned to
their own key by exportKey). /api/status additionally reports adapter_pools for
admins.
Measured with production's 29 MB audit copied to the test instance: startup RSS
19.0 MB (was 56 MB); scrolling 10 pages (1000 records) +0.7 MB; exporting the
full history (36441 rows / 4.4 MB CSV) +0.1 MB with no residual growth.
This commit is contained in:
JianFeeeee
@ -156,4 +156,347 @@ func TestLoadAuditFullReplay(t *testing.T) {
|
||||
if s.byStatus[200].Err != 0 || s.byStatus[503] == nil || s.byStatus[503].Reqs != 1 {
|
||||
t.Fatalf("by_status wrong: %#v", s.byStatus)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// ---- on-demand log loading (plan 阶段 3) ----
|
||||
|
||||
// writeAuditFile writes n synthetic request rows (plus some non-request event
|
||||
// rows, which must be skipped) and returns the path.
|
||||
func writeAuditFile(t *testing.T, path string, n int, key string, startMs int64) {
|
||||
t.Helper()
|
||||
f, err := os.Create(path)
|
||||
if err != nil {
|
||||
t.Fatalf("create audit: %v", err)
|
||||
}
|
||||
defer f.Close()
|
||||
for i := 0; i < n; i++ {
|
||||
fmt.Fprintf(f, `{"time":%d,"key":%q,"type":"chat","model":"m","source":"s","prompt_tokens":1,"completion_tokens":1,"latency_ms":5,"ok":true,"status":200}`+"\n",
|
||||
startMs+int64(i)*1000, key)
|
||||
if i%10 == 0 {
|
||||
// an access-log/event row: must never appear as a record
|
||||
fmt.Fprintf(f, `{"obj":"access","time":%d,"path":"/v1/models"}`+"\n", startMs+int64(i)*1000)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestLoadAuditBoundedTail is the startup-memory fix: only the tail of a large
|
||||
// audit file is replayed, and the ring stays capped.
|
||||
func TestLoadAuditBoundedTail(t *testing.T) {
|
||||
dir := t.TempDir()
|
||||
path := filepath.Join(dir, "audit.jsonl")
|
||||
writeAuditFile(t, path, 20000, "k1", 1_700_000_000_000)
|
||||
|
||||
fi, err := os.Stat(path)
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
orig := auditReplayBytes
|
||||
auditReplayBytes = 64 << 10 // 64 KB tail out of a much larger file
|
||||
defer func() { auditReplayBytes = orig }()
|
||||
if fi.Size() <= auditReplayBytes {
|
||||
t.Fatalf("fixture too small (%d bytes) to exercise bounded replay", fi.Size())
|
||||
}
|
||||
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
if !s.ReplayPartial() {
|
||||
t.Fatal("a truncated replay must be reported as partial")
|
||||
}
|
||||
snap := s.Snapshot(0, "")
|
||||
recs, _ := snap["records"].([]Req)
|
||||
if len(recs) == 0 {
|
||||
t.Fatal("bounded replay must still load the recent window")
|
||||
}
|
||||
if len(recs) > firstScreenRecords {
|
||||
t.Fatalf("snapshot shipped %d records, must be capped at the first screen (%d)",
|
||||
len(recs), firstScreenRecords)
|
||||
}
|
||||
// the aggregates must come from the tail only, not the whole file
|
||||
total, _ := snap["total"].(Stat)
|
||||
if total.Reqs == 0 {
|
||||
t.Fatal("tail replay must feed the aggregates")
|
||||
}
|
||||
if total.Reqs >= 20000 {
|
||||
t.Fatalf("aggregates replayed the whole file (%d reqs); replay must be bounded", total.Reqs)
|
||||
}
|
||||
}
|
||||
|
||||
// TestLoadAuditFullFileWhenSmall: a file inside the replay window is loaded
|
||||
// completely and is not flagged partial.
|
||||
func TestLoadAuditFullFileWhenSmall(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
writeAuditFile(t, path, 50, "k1", 1_700_000_000_000)
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
if s.ReplayPartial() {
|
||||
t.Fatal("a small file must be replayed in full, not flagged partial")
|
||||
}
|
||||
snap := s.Snapshot(0, "")
|
||||
total, _ := snap["total"].(Stat)
|
||||
if total.Reqs != 50 {
|
||||
t.Fatalf("total reqs = %d, want 50", total.Reqs)
|
||||
}
|
||||
}
|
||||
|
||||
// TestQuotaWindowsSurviveBoundedReplay is the regression guard the plan calls
|
||||
// out: shrinking the ring must not break token-quota accounting, which reads the
|
||||
// hour buckets rather than the ring.
|
||||
func TestQuotaWindowsSurviveBoundedReplay(t *testing.T) {
|
||||
s := NewStats(10) // deliberately tiny ring
|
||||
now := time.Now().UnixMilli()
|
||||
for i := 0; i < 100; i++ {
|
||||
s.Record(Req{Time: now, Key: "k", Model: "m", Source: "s", Prompt: 2, Compl: 3, OK: true, Status: 200})
|
||||
}
|
||||
if got := s.WindowTokens("m", "s", 24*hourSec); got != 500 {
|
||||
t.Fatalf("window tokens = %d, want 500 (quota accounting must not depend on the ring)", got)
|
||||
}
|
||||
if got := s.ModelTokens("k")["m"]; got != 500 {
|
||||
t.Fatalf("model tokens = %d, want 500", got)
|
||||
}
|
||||
if got := s.KeyTokens("k"); got != 500 {
|
||||
t.Fatalf("key tokens = %d, want 500", got)
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPagePagesBackwards walks the whole history one page at a time and
|
||||
// asserts strict newest-first order with no gaps or repeats.
|
||||
func TestAuditPagePagesBackwards(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
const n = 250
|
||||
writeAuditFile(t, path, n, "k1", 1_700_000_000_000)
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
|
||||
var seen []Req
|
||||
cursor := ""
|
||||
for i := 0; i < 20; i++ { // bounded loop guards against a cursor that never advances
|
||||
page := s.AuditPage(cursor, 40, "")
|
||||
if len(page.Records) == 0 {
|
||||
break
|
||||
}
|
||||
seen = append(seen, page.Records...)
|
||||
if !page.HasMore {
|
||||
break
|
||||
}
|
||||
if page.Next == cursor {
|
||||
t.Fatal("cursor did not advance")
|
||||
}
|
||||
cursor = page.Next
|
||||
}
|
||||
if len(seen) != n {
|
||||
t.Fatalf("paged %d records, want %d", len(seen), n)
|
||||
}
|
||||
for i := 1; i < len(seen); i++ {
|
||||
if seen[i-1].Time < seen[i].Time {
|
||||
t.Fatalf("records not newest-first at %d: %d then %d", i, seen[i-1].Time, seen[i].Time)
|
||||
}
|
||||
}
|
||||
// newest record first, oldest last
|
||||
if seen[0].Time != 1_700_000_000_000+int64(n-1)*1000 {
|
||||
t.Fatalf("first record time = %d, want the newest", seen[0].Time)
|
||||
}
|
||||
if seen[len(seen)-1].Time != 1_700_000_000_000 {
|
||||
t.Fatalf("last record time = %d, want the oldest", seen[len(seen)-1].Time)
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPageFirstScreenIsSmall: the first page must be exactly one screen,
|
||||
// independent of how large the audit file is.
|
||||
func TestAuditPageFirstScreenIsSmall(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
writeAuditFile(t, path, 5000, "k1", 1_700_000_000_000)
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
page := s.AuditPage("", 100, "")
|
||||
if len(page.Records) != 100 {
|
||||
t.Fatalf("first page = %d records, want 100", len(page.Records))
|
||||
}
|
||||
if !page.HasMore || page.Next == "" {
|
||||
t.Fatal("a large file must report more pages plus a cursor")
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPageFiltersByKey: a user key may only page its own records.
|
||||
func TestAuditPageFiltersByKey(t *testing.T) {
|
||||
dir := t.TempDir()
|
||||
path := filepath.Join(dir, "audit.jsonl")
|
||||
writeAuditFile(t, path, 30, "mine", 1_700_000_000_000)
|
||||
f, err := os.OpenFile(path, os.O_APPEND|os.O_WRONLY, 0644)
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
for i := 0; i < 30; i++ {
|
||||
fmt.Fprintf(f, `{"time":%d,"key":"other","type":"chat","model":"m","source":"s","ok":true,"status":200}`+"\n",
|
||||
1_700_000_100_000+int64(i)*1000)
|
||||
}
|
||||
f.Close()
|
||||
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
page := s.AuditPage("", 1000, "mine")
|
||||
if len(page.Records) != 30 {
|
||||
t.Fatalf("filtered page = %d records, want 30", len(page.Records))
|
||||
}
|
||||
for _, r := range page.Records {
|
||||
if r.Key != "mine" {
|
||||
t.Fatalf("key filter leaked record for %q", r.Key)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPageSpansRotatedFiles: paging must continue into .old files instead
|
||||
// of stopping at the live file's start.
|
||||
func TestAuditPageSpansRotatedFiles(t *testing.T) {
|
||||
dir := t.TempDir()
|
||||
path := filepath.Join(dir, "audit.jsonl")
|
||||
writeAuditFile(t, path, 40, "k1", 1_700_000_500_000) // newest
|
||||
writeAuditFile(t, path+".100.old", 40, "k1", 1_700_000_300_000) // older
|
||||
writeAuditFile(t, path+".050.old", 40, "k1", 1_700_000_100_000) // oldest
|
||||
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
var seen []Req
|
||||
cursor := ""
|
||||
for i := 0; i < 30; i++ {
|
||||
page := s.AuditPage(cursor, 25, "")
|
||||
seen = append(seen, page.Records...)
|
||||
if !page.HasMore {
|
||||
break
|
||||
}
|
||||
cursor = page.Next
|
||||
}
|
||||
if len(seen) != 120 {
|
||||
t.Fatalf("paged %d records across rotated files, want 120", len(seen))
|
||||
}
|
||||
for i := 1; i < len(seen); i++ {
|
||||
if seen[i-1].Time < seen[i].Time {
|
||||
t.Fatalf("rotation boundary broke the ordering at %d", i)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPageRotatedCursor: a cursor whose file rotated away must restart from
|
||||
// the newest page and say so, rather than silently returning nothing.
|
||||
func TestAuditPageRotatedCursor(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
writeAuditFile(t, path, 20, "k1", 1_700_000_000_000)
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
page := s.AuditPage("/gone/audit.jsonl:12345", 10, "")
|
||||
if !page.Rotated {
|
||||
t.Fatal("a stale cursor must be reported as rotated")
|
||||
}
|
||||
if len(page.Records) == 0 {
|
||||
t.Fatal("a stale cursor must fall back to the newest page")
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPageEmptyAndNoFile cover the degenerate inputs.
|
||||
func TestAuditPageEmptyAndNoFile(t *testing.T) {
|
||||
s := NewStats(0)
|
||||
if page := s.AuditPage("", 10, ""); len(page.Records) != 0 || page.HasMore {
|
||||
t.Fatalf("no audit path must yield an empty page, got %+v", page)
|
||||
}
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
if err := os.WriteFile(path, nil, 0644); err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
s2 := NewStats(0)
|
||||
s2.LoadAudit(path)
|
||||
if page := s2.AuditPage("", 10, ""); len(page.Records) != 0 || page.HasMore {
|
||||
t.Fatalf("empty audit file must yield an empty page, got %+v", page)
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditPageHandlesLongLines: a record larger than the reverse-read chunk
|
||||
// must still be decoded (the reader carries partial lines across chunks).
|
||||
func TestAuditPageHandlesLongLines(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
f, err := os.Create(path)
|
||||
if err != nil {
|
||||
t.Fatal(err)
|
||||
}
|
||||
big := strings.Repeat("e", revChunk+1024) // one record spanning >1 chunk
|
||||
fmt.Fprintf(f, `{"time":1,"key":"k","type":"chat","model":"m","source":"s","ok":false,"status":500,"error":%q}`+"\n", big)
|
||||
fmt.Fprintf(f, `{"time":2,"key":"k","type":"chat","model":"m","source":"s","ok":true,"status":200}`+"\n")
|
||||
f.Close()
|
||||
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
page := s.AuditPage("", 10, "")
|
||||
if len(page.Records) != 2 {
|
||||
t.Fatalf("got %d records, want 2 (a >chunk record must survive reverse reads)", len(page.Records))
|
||||
}
|
||||
if page.Records[0].Time != 2 || page.Records[1].Time != 1 {
|
||||
t.Fatalf("ordering broken: %d then %d", page.Records[0].Time, page.Records[1].Time)
|
||||
}
|
||||
if len(page.Records[1].Err) != len(big) {
|
||||
t.Fatalf("oversized field truncated: %d bytes, want %d", len(page.Records[1].Err), len(big))
|
||||
}
|
||||
}
|
||||
|
||||
// TestStreamAuditRecordsIsWindowed: export streaming must honour the time window
|
||||
// and the key filter, and must hand records over one at a time.
|
||||
func TestStreamAuditRecordsIsWindowed(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
writeAuditFile(t, path, 100, "k1", 1_700_000_000_000)
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
|
||||
from := int64(1_700_000_010_000)
|
||||
to := int64(1_700_000_019_000)
|
||||
var got []Req
|
||||
if err := s.StreamAuditRecords(from, to, "", func(r Req) error {
|
||||
got = append(got, r)
|
||||
return nil
|
||||
}); err != nil {
|
||||
t.Fatalf("stream: %v", err)
|
||||
}
|
||||
if len(got) != 10 {
|
||||
t.Fatalf("streamed %d records, want 10 in [%d,%d]", len(got), from, to)
|
||||
}
|
||||
for _, r := range got {
|
||||
if r.Time < from || r.Time > to {
|
||||
t.Fatalf("record outside the window: %d", r.Time)
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// TestStreamAuditRecordsAbortStops: a callback error (client disconnect) must
|
||||
// stop the walk immediately instead of reading the rest of the history.
|
||||
func TestStreamAuditRecordsAbortStops(t *testing.T) {
|
||||
path := filepath.Join(t.TempDir(), "audit.jsonl")
|
||||
writeAuditFile(t, path, 500, "k1", 1_700_000_000_000)
|
||||
s := NewStats(0)
|
||||
s.LoadAudit(path)
|
||||
|
||||
seen := 0
|
||||
stop := fmt.Errorf("client gone")
|
||||
err := s.StreamAuditRecords(0, 0, "", func(Req) error {
|
||||
seen++
|
||||
if seen == 5 {
|
||||
return stop
|
||||
}
|
||||
return nil
|
||||
})
|
||||
if err != stop {
|
||||
t.Fatalf("abort must surface the callback error, got %v", err)
|
||||
}
|
||||
if seen != 5 {
|
||||
t.Fatalf("walk continued after abort: %d records", seen)
|
||||
}
|
||||
}
|
||||
|
||||
// TestAuditRotationThresholds pins the smaller-file/more-files trade-off that
|
||||
// makes reverse paging cheap while keeping the same total budget.
|
||||
func TestAuditRotationThresholds(t *testing.T) {
|
||||
if auditRotateBytes != 16<<20 {
|
||||
t.Fatalf("auditRotateBytes = %d, want 16 MiB", auditRotateBytes)
|
||||
}
|
||||
if auditKeepOld != 16 {
|
||||
t.Fatalf("auditKeepOld = %d, want 16", auditKeepOld)
|
||||
}
|
||||
if total := auditRotateBytes * int64(auditKeepOld); total != 256<<20 {
|
||||
t.Fatalf("total audit budget = %d, want 256 MiB", total)
|
||||
}
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user