From 0acaabe04f42c1d212a82d47d6c726d75f79efa1 Mon Sep 17 00:00:00 2001 From: hallelx2 Date: Mon, 28 Sep 2026 03:21:51 +0100 Subject: [PATCH 1/2] perf: take llmgate's guard fix; log and report where Judge time goes The Judge client rebuilt its tokenizer on every count, 256 ms a time, once per question, inside the limiter's slot (HAL-1708). Taking the fix, same engine code, first 12 FinanceBench questions, back to back: llmgate v0.5.0 median 50.5 s 12/12 4.2 req $0.00368 llmgate 010e07c median 2.2 s 12/12 4.2 req $0.00369 The provider did identical work. The 37-to-50-second query was our own CPU, and nothing reported it: a round-trip number cannot tell local preparation from the provider. So every Judge request now reports itself. The engine and server log each one at debug, and warn when local preparation passes 250 ms, which is a few milliseconds when healthy. navbench and tocdump print prepare, first-byte and total percentiles at the end of a run. The Judge is warmed at startup so the first query does not open the connection or build the tokenizer. llmgate is pinned to the fix's commit until its PR merges and is tagged. --- cmd/engine/judge_log_test.go | 27 ++++++++++ cmd/engine/main.go | 49 +++++++++++++++-- cmd/navbench/main.go | 5 +- cmd/server/main.go | 49 +++++++++++++++-- cmd/tocdump/main.go | 9 ++-- go.mod | 2 +- go.sum | 2 + internal/judgestats/judgestats.go | 75 ++++++++++++++++++++++++++ internal/judgestats/judgestats_test.go | 48 +++++++++++++++++ 9 files changed, 251 insertions(+), 15 deletions(-) create mode 100644 cmd/engine/judge_log_test.go create mode 100644 internal/judgestats/judgestats.go create mode 100644 internal/judgestats/judgestats_test.go diff --git a/cmd/engine/judge_log_test.go b/cmd/engine/judge_log_test.go new file mode 100644 index 0000000..0a8090f --- /dev/null +++ b/cmd/engine/judge_log_test.go @@ -0,0 +1,27 @@ +package main + +import ( + "bytes" + "log/slog" + "strings" + "testing" + "time" + + "github.com/hallelx2/llmgate/judge/typesafe" +) + +// Slow local preparation is what hid HAL-1708 for a week; it must be +// loud, and a healthy request must not be. +func TestJudgeRequestLoggerWarnsOnlyOnSlowPreparation(t *testing.T) { + var buf bytes.Buffer + log := judgeRequestLogger(slog.New(slog.NewTextHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}))) + + log(typesafe.RequestTrace{Prepare: 3 * time.Millisecond, FirstByte: 900 * time.Millisecond}) + if buf.Len() != 0 { + t.Fatalf("a healthy request logged at info or above: %s", buf.String()) + } + log(typesafe.RequestTrace{Prepare: 4 * time.Second, Questions: 120}) + if !strings.Contains(buf.String(), "slow request preparation") || !strings.Contains(buf.String(), "prepare_ms=4000") { + t.Errorf("slow preparation not reported: %s", buf.String()) + } +} diff --git a/cmd/engine/main.go b/cmd/engine/main.go index 74a22b4..3b2a887 100644 --- a/cmd/engine/main.go +++ b/cmd/engine/main.go @@ -133,7 +133,7 @@ func run() error { if llmClient != nil { llmClient = limit.Client(newLimiter("llm", cfg.LLM.Concurrency, logger))(llmClient) } - judge, err := buildJudge(cfg.LLM.Judge, newLimiter("judge", cfg.LLM.Concurrency, logger)) + judge, err := buildJudge(cfg.LLM.Judge, newLimiter("judge", cfg.LLM.Concurrency, logger), logger) if err != nil { logger.Error("judge: config invalid", "err", err) os.Exit(1) @@ -440,23 +440,62 @@ func newLimiter(name string, c config.ConcurrencyBlock, logger *slog.Logger) *li }) } -func buildJudge(c config.JudgeBlock, lim *limit.Limiter) (llmgate.Judge, error) { +func buildJudge(c config.JudgeBlock, lim *limit.Limiter, logger *slog.Logger) (llmgate.Judge, error) { if c.TypeSafe.APIKey == "" { return nil, nil } j, err := typesafe.New(typesafe.Config{ - APIKey: c.TypeSafe.APIKey, - BaseURL: c.TypeSafe.BaseURL, - Model: c.TypeSafe.Model, + APIKey: c.TypeSafe.APIKey, + BaseURL: c.TypeSafe.BaseURL, + Model: c.TypeSafe.Model, + OnRequest: judgeRequestLogger(logger), }) if err != nil { return nil, err } + // Open the connection and build the guard's tokenizer now, so the + // first query after boot does not pay for either. + go func() { + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + if err := j.Warm(ctx); err != nil { + logger.Warn("judge: warm-up failed; the first request will open its own connection", "err", err) + } + }() // The limiter sits inside retry: each attempt takes a slot, and the // failure that triggers a retry has already narrowed the limit. return retry.NewJudge(retry.Config{MaxRetries: 3})(limit.Judge(lim)(j)), nil } +// judgeSlowPrepare is local work before a Judge request goes on the +// wire that deserves a warning. It is a few milliseconds when healthy; +// the guard rebuilding its tokenizer made it seconds, and nothing said +// so until a latency evaluation could not account for a factor of three +// (HAL-1708). +const judgeSlowPrepare = 250 * time.Millisecond + +// judgeRequestLogger logs where each Judge request's time went: debug +// always, a warning when local preparation — not the provider — is slow. +func judgeRequestLogger(logger *slog.Logger) func(typesafe.RequestTrace) { + return func(tr typesafe.RequestTrace) { + attrs := []any{ + "questions", tr.Questions, "state_bytes", tr.StateBytes, + "prepare_ms", tr.Prepare.Milliseconds(), "guard_counted", tr.GuardCounted, + "connect_ms", tr.Connect.Milliseconds(), "conn_reused", tr.ConnReused, + "first_byte_ms", tr.FirstByte.Milliseconds(), "total_ms", tr.Total.Milliseconds(), + "status", tr.StatusCode, "input_tokens", tr.InputTokens, + } + if tr.Err != nil { + attrs = append(attrs, "err", tr.Err) + } + if tr.Prepare > judgeSlowPrepare { + logger.Warn("judge: slow request preparation — local CPU, not the provider", attrs...) + return + } + logger.Debug("judge: request", attrs...) + } +} + func buildLLM(c config.LLMConfig) (llmgate.Client, error) { switch c.Driver { case "anthropic": diff --git a/cmd/navbench/main.go b/cmd/navbench/main.go index b07bc12..02f5336 100644 --- a/cmd/navbench/main.go +++ b/cmd/navbench/main.go @@ -26,6 +26,7 @@ import ( "github.com/hallelx2/llmgate/middleware/limit" "github.com/hallelx2/llmgate/middleware/retry" + "github.com/hallelx2/vectorless-engine/internal/judgestats" "github.com/hallelx2/vectorless-engine/pkg/ingest" "github.com/hallelx2/vectorless-engine/pkg/parser" "github.com/hallelx2/vectorless-engine/pkg/retrieval" @@ -76,13 +77,14 @@ func main() { limitQ := flag.Int("limit", 0, "stop after this many questions (0 = all)") parallel := flag.Int("parallel", 1, "questions in flight at once; the provider's adaptive limiter governs requests") flag.Parse() + stats := &judgestats.Recorder{} if *qPath == "" || *trees == "" || *pdfs == "" { fmt.Fprintln(os.Stderr, "usage: navbench -questions q.jsonl -trees dir -pdfs dir [-out o.jsonl]") os.Exit(2) } key := os.Getenv(typesafe.EnvAPIKey) - tj, err := typesafe.New(typesafe.Config{APIKey: key}) + tj, err := typesafe.New(typesafe.Config{APIKey: key, OnRequest: stats.Observe}) if err != nil { fmt.Fprintln(os.Stderr, "judge:", err) os.Exit(1) @@ -188,6 +190,7 @@ func main() { wg.Wait() fmt.Printf("\nwall %.1fs for %d questions at parallel=%d; limiter now %d\n", time.Since(runStart).Seconds(), len(qs), *parallel, lim.Limit()) summarise(results) + stats.Summary(os.Stdout) } func load(doc, trees, pdfs string, leafCache map[string][]retrieval.NavLeaf, pageCache map[string][]ingest.PageText) ([]retrieval.NavLeaf, []ingest.PageText, error) { diff --git a/cmd/server/main.go b/cmd/server/main.go index b6f1728..0d6d2d4 100644 --- a/cmd/server/main.go +++ b/cmd/server/main.go @@ -147,7 +147,7 @@ func run() error { return fmt.Errorf("init llm: %w", err) } llmClient = limit.Client(newLimiter("llm", cfg.Engine.LLM.Concurrency, logger))(llmClient) - judge, err := buildJudge(cfg.Engine.LLM.Judge, newLimiter("judge", cfg.Engine.LLM.Concurrency, logger)) + judge, err := buildJudge(cfg.Engine.LLM.Judge, newLimiter("judge", cfg.Engine.LLM.Concurrency, logger), logger) if err != nil { logger.Error("judge: config invalid", "err", err) os.Exit(1) @@ -437,23 +437,62 @@ func newLimiter(name string, c enginecfg.ConcurrencyBlock, logger *slog.Logger) }) } -func buildJudge(c enginecfg.JudgeBlock, lim *limit.Limiter) (llmgate.Judge, error) { +func buildJudge(c enginecfg.JudgeBlock, lim *limit.Limiter, logger *slog.Logger) (llmgate.Judge, error) { if c.TypeSafe.APIKey == "" { return nil, nil } j, err := typesafe.New(typesafe.Config{ - APIKey: c.TypeSafe.APIKey, - BaseURL: c.TypeSafe.BaseURL, - Model: c.TypeSafe.Model, + APIKey: c.TypeSafe.APIKey, + BaseURL: c.TypeSafe.BaseURL, + Model: c.TypeSafe.Model, + OnRequest: judgeRequestLogger(logger), }) if err != nil { return nil, err } + // Open the connection and build the guard's tokenizer now, so the + // first query after boot does not pay for either. + go func() { + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + if err := j.Warm(ctx); err != nil { + logger.Warn("judge: warm-up failed; the first request will open its own connection", "err", err) + } + }() // The limiter sits inside retry: each attempt takes a slot, and the // failure that triggers a retry has already narrowed the limit. return retry.NewJudge(retry.Config{MaxRetries: 3})(limit.Judge(lim)(j)), nil } +// judgeSlowPrepare is local work before a Judge request goes on the +// wire that deserves a warning. It is a few milliseconds when healthy; +// the guard rebuilding its tokenizer made it seconds, and nothing said +// so until a latency evaluation could not account for a factor of three +// (HAL-1708). +const judgeSlowPrepare = 250 * time.Millisecond + +// judgeRequestLogger logs where each Judge request's time went: debug +// always, a warning when local preparation — not the provider — is slow. +func judgeRequestLogger(logger *slog.Logger) func(typesafe.RequestTrace) { + return func(tr typesafe.RequestTrace) { + attrs := []any{ + "questions", tr.Questions, "state_bytes", tr.StateBytes, + "prepare_ms", tr.Prepare.Milliseconds(), "guard_counted", tr.GuardCounted, + "connect_ms", tr.Connect.Milliseconds(), "conn_reused", tr.ConnReused, + "first_byte_ms", tr.FirstByte.Milliseconds(), "total_ms", tr.Total.Milliseconds(), + "status", tr.StatusCode, "input_tokens", tr.InputTokens, + } + if tr.Err != nil { + attrs = append(attrs, "err", tr.Err) + } + if tr.Prepare > judgeSlowPrepare { + logger.Warn("judge: slow request preparation — local CPU, not the provider", attrs...) + return + } + logger.Debug("judge: request", attrs...) + } +} + func buildLLM(c enginecfg.LLMConfig) (llmgate.Client, error) { switch c.Driver { case "anthropic": diff --git a/cmd/tocdump/main.go b/cmd/tocdump/main.go index 13f17b3..279563e 100644 --- a/cmd/tocdump/main.go +++ b/cmd/tocdump/main.go @@ -32,6 +32,7 @@ import ( "github.com/hallelx2/llmgate/middleware/retry" "github.com/hallelx2/llmgate/provider/anthropic" + "github.com/hallelx2/vectorless-engine/internal/judgestats" "github.com/hallelx2/vectorless-engine/pkg/ingest" "github.com/hallelx2/vectorless-engine/pkg/parser" "github.com/hallelx2/vectorless-engine/pkg/tree" @@ -63,6 +64,7 @@ func main() { parallel := flag.Int("parallel", 1, "documents in flight at once; the provider's adaptive limiter governs requests") split := flag.Int("split", 0, "split leaves spanning more than this many pages into sub-leaves (0 = default 20, negative = off)") flag.Parse() + stats := &judgestats.Recorder{} if *parallel < 1 { *parallel = 1 } @@ -85,7 +87,7 @@ func main() { } var judge llmgate.Judge if !*noJudge { - if judge, err = buildJudge(); err != nil { + if judge, err = buildJudge(stats); err != nil { fmt.Fprintln(os.Stderr, "judge:", err) os.Exit(1) } @@ -143,6 +145,7 @@ func main() { } wg.Wait() fmt.Printf(" wall %.1fs for %d documents at parallel=%d; limiter now %d\n", time.Since(runStart).Seconds(), len(pdfs), *parallel, lim.Limit()) + stats.Summary(os.Stdout) } func write(dir string, d dump) { @@ -172,7 +175,7 @@ func countLeaves(ns []tree.TOCNode) int { // sharing sixty lines is not yet worth an internal package; if a third // appears, it is. -func buildJudge() (llmgate.Judge, error) { +func buildJudge(stats *judgestats.Recorder) (llmgate.Judge, error) { key := os.Getenv(typesafe.EnvAPIKey) if key == "" { key = dotEnv(typesafe.EnvAPIKey) @@ -180,7 +183,7 @@ func buildJudge() (llmgate.Judge, error) { if key == "" { return nil, fmt.Errorf("no %s", typesafe.EnvAPIKey) } - j, err := typesafe.New(typesafe.Config{APIKey: key}) + j, err := typesafe.New(typesafe.Config{APIKey: key, OnRequest: stats.Observe}) if err != nil { return nil, err } diff --git a/go.mod b/go.mod index ddd69bc..1e6a1f3 100644 --- a/go.mod +++ b/go.mod @@ -14,7 +14,7 @@ require ( github.com/aws/smithy-go v1.25.0 github.com/go-chi/chi/v5 v5.2.5 github.com/google/uuid v1.6.0 - github.com/hallelx2/llmgate v0.5.0 + github.com/hallelx2/llmgate v0.5.1-0.20260928015141-010e07c576e6 github.com/hallelx2/pdftable v0.4.0 github.com/hibiken/asynq v0.26.0 github.com/jackc/pgx/v5 v5.9.2 diff --git a/go.sum b/go.sum index 58c27dc..beda7ed 100644 --- a/go.sum +++ b/go.sum @@ -138,6 +138,8 @@ github.com/hallelx2/llmgate v0.4.1-0.20260918182842-b2ec96425ecc h1:4b6tUdYQANqf github.com/hallelx2/llmgate v0.4.1-0.20260918182842-b2ec96425ecc/go.mod h1:WpKwV/utKOmb+G5DwezSGjmGtz9D5I6MuS4MqAs7rkA= github.com/hallelx2/llmgate v0.5.0 h1:yNBm7NOtDrCnpeMPz2BqbNcCJeUTw0WN6oiIuEFankg= github.com/hallelx2/llmgate v0.5.0/go.mod h1:WpKwV/utKOmb+G5DwezSGjmGtz9D5I6MuS4MqAs7rkA= +github.com/hallelx2/llmgate v0.5.1-0.20260928015141-010e07c576e6 h1:26w9OIBo0Cfu5vAVyjZgr0Uyh25B+p4jSg2dit6BuBI= +github.com/hallelx2/llmgate v0.5.1-0.20260928015141-010e07c576e6/go.mod h1:WpKwV/utKOmb+G5DwezSGjmGtz9D5I6MuS4MqAs7rkA= github.com/hallelx2/pdftable v0.4.0 h1:ldF8qQrUbejWsbB/JSIqliEXF2jF8z8kjEsbKS8r2BU= github.com/hallelx2/pdftable v0.4.0/go.mod h1:pxNlc4D43wjzis7M6EfgQZvHOsQ4okggm+xqUu+OokI= github.com/hhrutter/lzw v1.0.0 h1:laL89Llp86W3rRs83LvKbwYRx6INE8gDn0XNb1oXtm0= diff --git a/internal/judgestats/judgestats.go b/internal/judgestats/judgestats.go new file mode 100644 index 0000000..ec7b5d9 --- /dev/null +++ b/internal/judgestats/judgestats.go @@ -0,0 +1,75 @@ +// Package judgestats collects typesafe.RequestTrace records from a +// benchmark run and summarises where Judge request time went — local +// preparation against the provider's own time — so a latency number is +// never again reported without saying whose latency it is (HAL-1708). +package judgestats + +import ( + "fmt" + "io" + "sort" + "sync" + "time" + + "github.com/hallelx2/llmgate/judge/typesafe" +) + +// Recorder accumulates traces; safe for concurrent use. +type Recorder struct { + mu sync.Mutex + traces []typesafe.RequestTrace +} + +// Observe is a typesafe.Config.OnRequest hook. +func (r *Recorder) Observe(tr typesafe.RequestTrace) { + r.mu.Lock() + r.traces = append(r.traces, tr) + r.mu.Unlock() +} + +// Summary writes one block of percentiles to w. +func (r *Recorder) Summary(w io.Writer) { + r.mu.Lock() + ts := append([]typesafe.RequestTrace(nil), r.traces...) + r.mu.Unlock() + if len(ts) == 0 { + return + } + pick := func(f func(typesafe.RequestTrace) time.Duration) []time.Duration { + out := make([]time.Duration, len(ts)) + for i, t := range ts { + out[i] = f(t) + } + sort.Slice(out, func(i, j int) bool { return out[i] < out[j] }) + return out + } + pct := func(ds []time.Duration, p float64) time.Duration { + return ds[min(len(ds)-1, int(p*float64(len(ds))))] + } + counted, reused, failed := 0, 0, 0 + for _, t := range ts { + if t.GuardCounted { + counted++ + } + if t.ConnReused { + reused++ + } + if t.Err != nil { + failed++ + } + } + fmt.Fprintf(w, "\njudge requests %d (failed %d, tokenised by the guard %d, on a reused connection %d)\n", len(ts), failed, counted, reused) + for _, row := range []struct { + name string + ds []time.Duration + }{ + {"prepare (local)", pick(func(t typesafe.RequestTrace) time.Duration { return t.Prepare })}, + {"first byte (provider)", pick(func(t typesafe.RequestTrace) time.Duration { return t.FirstByte })}, + {"total", pick(func(t typesafe.RequestTrace) time.Duration { return t.Total })}, + } { + fmt.Fprintf(w, " %-22s p50 %7.0fms p95 %7.0fms max %7.0fms\n", row.name, + ms(pct(row.ds, 0.5)), ms(pct(row.ds, 0.95)), ms(row.ds[len(row.ds)-1])) + } +} + +func ms(d time.Duration) float64 { return float64(d) / float64(time.Millisecond) } diff --git a/internal/judgestats/judgestats_test.go b/internal/judgestats/judgestats_test.go new file mode 100644 index 0000000..98b7bfd --- /dev/null +++ b/internal/judgestats/judgestats_test.go @@ -0,0 +1,48 @@ +package judgestats + +import ( + "bytes" + "errors" + "strings" + "sync" + "testing" + "time" + + "github.com/hallelx2/llmgate/judge/typesafe" +) + +func TestSummarySeparatesLocalFromProviderTime(t *testing.T) { + r := &Recorder{} + var wg sync.WaitGroup + for i := 1; i <= 20; i++ { + wg.Add(1) + go func() { + defer wg.Done() + r.Observe(typesafe.RequestTrace{ + Prepare: time.Duration(i) * time.Millisecond, + FirstByte: time.Duration(i) * 100 * time.Millisecond, + Total: time.Duration(i)*100*time.Millisecond + time.Duration(i)*time.Millisecond, + GuardCounted: i%2 == 0, + ConnReused: i > 1, + }) + }() + } + r.Observe(typesafe.RequestTrace{Err: errors.New("529")}) + wg.Wait() + var buf bytes.Buffer + r.Summary(&buf) + out := buf.String() + for _, want := range []string{"judge requests 21 (failed 1, tokenised by the guard 10, on a reused connection 19)", "prepare (local)", "first byte (provider)", "max 2000ms"} { + if !strings.Contains(out, want) { + t.Errorf("summary missing %q:\n%s", want, out) + } + } +} + +func TestEmptySummaryPrintsNothing(t *testing.T) { + var buf bytes.Buffer + (&Recorder{}).Summary(&buf) + if buf.Len() != 0 { + t.Errorf("got %q", buf.String()) + } +} From ff21cb4cb8963d0c94aeba9ecaf24c2117a425c9 Mon Sep 17 00:00:00 2001 From: hallelx2 Date: Mon, 28 Sep 2026 04:13:58 +0100 Subject: [PATCH 2/2] =?UTF-8?q?docs:=20evaluation=20=E2=80=94=20the=2050-s?= =?UTF-8?q?econd=20query=20was=20our=20own=20CPU?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Measured before and after the guard fix, the ingest fan-out and the retrieval skim, on the FinanceBench corpus: query median 50.5 s to 1.9 s at 36/40 and a lower cost per question, ingest median 66.1 s to 4.1 s per filing at 47/47. Marks the 2026-09-25 latency figures as superseded. --- ...ery-latency-and-the-embedding-prefilter.md | 2 + .../2026-09-28-latency-was-our-cpu.md | 102 ++++++++++++++++++ 2 files changed, 104 insertions(+) create mode 100644 docs/evaluations/2026-09-28-latency-was-our-cpu.md diff --git a/docs/evaluations/2026-09-25-query-latency-and-the-embedding-prefilter.md b/docs/evaluations/2026-09-25-query-latency-and-the-embedding-prefilter.md index e6d185d..73288a9 100644 --- a/docs/evaluations/2026-09-25-query-latency-and-the-embedding-prefilter.md +++ b/docs/evaluations/2026-09-25-query-latency-and-the-embedding-prefilter.md @@ -6,6 +6,8 @@ **Issues:** HAL-1371, HAL-1542 **Question:** judgewalk answers in 37 s at the median. Retrieval systems people compare us to answer in 49 ms. How much of the gap is recoverable, and by what? +> **Superseded 2026-09-28.** The latencies here were measured with the llmgate guard rebuilding its tokenizer on every count, which was most of the time. The unexplained factor of three in §1 was that bug. See [`2026-09-28-latency-was-our-cpu.md`](2026-09-28-latency-was-our-cpu.md). The recall tables in §2 are unaffected. + ## Result: most of it is request shape, not work. A local pre-filter cannot help at any scale; batching can. ## 1. Request shape barely matters. Two of my own bugs did. diff --git a/docs/evaluations/2026-09-28-latency-was-our-cpu.md b/docs/evaluations/2026-09-28-latency-was-our-cpu.md new file mode 100644 index 0000000..ca7b1bc --- /dev/null +++ b/docs/evaluations/2026-09-28-latency-was-our-cpu.md @@ -0,0 +1,102 @@ +# The 50-second query was our own CPU + +**Date:** 2026-09-28 +**Harness:** [`cmd/navbench`](../../cmd/navbench/main.go), [`cmd/tocdump`](../../cmd/tocdump/main.go) with `coverage.py` and `titles.py`, llmgate `judge/typesafe` benchmarks +**Corpus:** FinanceBench, 21 filings with trees (the 19 with questions plus two), 40 questions, trees `trees-split-20c` +**Issues:** HAL-1708 (llmgate), HAL-1545 (ingest fan-out), HAL-1566 (retrieval skim), HAL-1563 (post-fix baseline) +**Supersedes:** every latency figure in [`2026-09-25-query-latency-and-the-embedding-prefilter.md`](2026-09-25-query-latency-and-the-embedding-prefilter.md) and the 37 s / 58 s figures in [`2026-09-25-judgement-not-generation.md`](2026-09-25-judgement-not-generation.md) + +## Result + +| | before | after | accuracy | cost | +|---|---|---|---|---| +| query, median | 50.5 s | **1.9 s** | 36/40 every gold page, unchanged | $0.00402 → **$0.00388** | +| ingest, median per filing | 66.1 s | **4.1 s** | 47/47 gold pages covered, unchanged | $0.133 → $0.133 for 21 filings | + +Accuracy and cost did not move because the provider was never the bottleneck. Jev answered in about 0.6 s at the median throughout. The time went to our client preparing each request. + +## 1. The guard rebuilt its tokenizer on every count + +llmgate's TypeSafe client checks each request against the provider's context limits before sending it. It counted tokens with `tiktoken.GetEncoding("cl100k_base")`, and tiktoken-go v0.1.6 caches the rank table but builds a new BPE on every call: a 100k-entry decoder map and a regex compile. That cost 256 ms. The guard counted the state and then each question separately, so the 120-question section ranking spent around 30 s of CPU before it went on the wire. It did so inside the concurrency limiter's slot, where it looked like a slow provider. + +This was the factor of three the 2026-09-25 evaluation could not account for (predicted ~9 s, measured 28.6 s). It hit ingest too: `batchByTokens` and the resolver count every page to pack batches. + +The fix (llmgate PR #19): + +- build the encoder once per process; +- decide on byte length first, because every cl100k token covers at least one byte — when the bytes fit, the tokens fit, and nothing is counted; +- past that bound, count the state once, cut into pieces the pre-tokenizer cannot span and counted in parallel. The count is exact, and a property test holds it equal to the serial count. + +| llmgate benchmark | before | after | +|---|---|---| +| count one short question | 256 ms | 0.1 ms | +| 16-page request, end to end against a stub | 289 ms | 63 ms | +| 120-head skim request, end to end against a stub | 163 ms | 45 ms | + +Same engine code, only llmgate swapped, first 12 questions, run back to back: + +| llmgate | hit | requests/q | input tokens/q | $/q | median | +|---|---|---|---|---|---| +| v0.5.0 | 12/12 | 4.2 | 87,711 | 0.00368 | 50.5 s | +| 010e07c | 12/12 | 4.2 | 87,771 | 0.00369 | **2.2 s** | + +Identical requests, tokens and cost. The 28.6 s quoted on 2026-09-25 came from the same bug on a less loaded machine. It should not be cited again. + +Every Judge request now reports prepare time, connect, time to first byte and total (`typesafe.Config.OnRequest`). The engine warns when preparation passes 250 ms, and both benches print the split. Across the runs below, preparation was 1–35 ms at the median and the provider's first byte 450–640 ms. + +## 2. Ingest sent its batches one at a time + +Six Judge loops in the TOC stage — detection fan-out, detection, verification, contents confirmation, page resolution, heading split — built a batch, sent it, waited, then built the next. The batches were independent. They are now built first and sent together, and the leaf splitter handles every leaf of a generation at once. The 24k request budget stays; HAL-1545's proposal to cut it to 6k rested on a probe the earlier evaluation retracted. + +All 21 filings, one at a time, Judge-only, minimal context: + +| build | median / filing | p90 | max | total build | requests | cost | coverage | +|---|---|---|---|---|---|---|---| +| original | 66.1 s | 126.0 s | 456.5 s | 1,673 s | 288 | $0.1331 | 47/47 | +| + tokenizer fix | 8.8 s | 17.2 s | 49.4 s | 234 s | 287 | $0.1316 | 47/47 | +| + batch fan-out | **4.1 s** | **6.8 s** | **15.9 s** | **105 s** | 282 | $0.1330 | 47/47 | + +The tokenizer fix is most of it. Fan-out halves what is left. + +Title recall against the original build is 0.944 for the fan-out and 0.949 for the tokenizer fix alone. The tokenizer fix does not change which questions are asked, so 0.949 measures Jev's run-to-run variation in the trees, and the fan-out sits inside it. HAL-1545's acceptance of "≥ 0.96 against the current trees" cannot be met by re-running unchanged code and should be read against this floor. + +## 3. Retrieval: one level removed, fewer pages read + +With the guard fixed, a query is its four sequential levels at ~0.6 s each: rank sections, skim page heads, read the best pages, maybe follow a cross-reference. The skim waited on the ranking only to learn which pages to skim. Skimming every page's head in the same round as the ranking removes that level (HAL-1566). The full read is chosen from the same candidates by the same scores, and a unit test holds the two paths equal. + +40 questions, repeated runs: + +| mode | hit (every gold page) | median | requests/q | $/q | +|---|---|---|---|---| +| sequential skim, 40 pages | 36, 35, 36 | 2.5, 2.7, 3.1 s | 4.3 | 0.00402 | +| skim-all, 40 pages | 35, 36, 35 | 1.7, 1.7, 1.8 s | 4.8 | 0.00431 | +| skim-all, 30 pages | 36, 36, **36** | 1.8, 2.0, **1.9** s | 4.4 | **0.00388** | +| skim-all, 20 pages | 35, 36 | 1.9, 1.7 s | 3.9 | 0.00345 | + +The questions that change between runs are the same two in every mode (Pfizer 0030, Verizon 0215). No mode differs in accuracy beyond that noise. Skimming every page costs ~7% at 40 pages. Reading 30 pages in full instead of 40 recovers that and more: full pages are ~60% of a query's tokens. The shipped default is skim-all at 30 pages. 20 matched on this corpus, but FinanceBench rarely spreads an answer across pages, and a smaller read would hurt those questions first. + +Skim-all is on only in the persisted-pages path, where every page is already in memory, and only for documents up to 400 pages. + +## What this does not claim + +- The 1.9 s is `navbench`, which calls the navigator directly. It excludes the HTTP API, the database reads for the TOC and pages, and answer generation. `/v1/query` over the deployed engine has not been re-measured. +- Runs from 03:40 onward shared the machine with a headless Chromium, an Android emulator and the original-code ingest run. Load average peaked at 68 on 8 cores. Accuracy comparisons are unaffected. Absolute latencies from those runs are, if anything, pessimistic. +- The misses are the known ones — three Boeing, one Pfizer, one Verizon multi-page — and none was touched. +- Multi-hop is still unmeasured. + +## Reproduce + +```bash +# llmgate +go test -run XXX -bench . ./judge/typesafe/ + +# retrieval, shipped defaults +go run ./cmd/navbench -questions ~/.cache/vlbench/financebench-questions.jsonl \ + -trees ~/.cache/vlbench/trees-split-20c -pdfs ~/.cache/vlbench/financebench -skim-all + +# ingest +go run ./cmd/tocdump -docs ~/.cache/vlbench/financebench -out /tmp/t -judge-only -minimal -parallel 1 +uv run --project ../vectorless-bench python cmd/tocdump/coverage.py /tmp/t +``` + +Both benches end with a `judge requests` block separating local preparation from provider time. A latency figure quoted without it does not say whose latency it is.