From f229795ceaeaf6443a5220fdc97f74b79060d882 Mon Sep 17 00:00:00 2001 From: claude Date: Mon, 3 Aug 2026 23:19:03 +0400 Subject: [PATCH 1/3] phraser: forward llama-server's output to mavend's log (V-499) mavend scraped the child's stderr for the listen line and threw every other line away, and never piped its stdout at all. Nothing about the resident model's memory was diagnosable from a running box: no buffer sizes, no KV-cache layout, no offload lines, no prompt-cache limit. Both streams now share one pipe and every line lands in mavend's log with a `llama:` prefix. The last 12 startup lines are also kept and go into the error when the server dies before it listens, because bare "EOF" never named which allocation it choked on. Co-Authored-By: Claude Opus 5 --- internal/phraser/llmphraser.go | 134 +++++++++++++++++++++++++-------- internal/phraser/spawn_test.go | 74 +++++++++++++++--- 2 files changed, 165 insertions(+), 43 deletions(-) diff --git a/internal/phraser/llmphraser.go b/internal/phraser/llmphraser.go index 67970c9..d0e79bf 100644 --- a/internal/phraser/llmphraser.go +++ b/internal/phraser/llmphraser.go @@ -1,6 +1,7 @@ package phraser import ( + "bufio" "bytes" "context" "encoding/json" @@ -8,6 +9,7 @@ import ( "io" "log" "net/http" + "os" "os/exec" "regexp" "strings" @@ -83,6 +85,19 @@ type Config struct { NCtx int Timeout time.Duration + // CacheRAMMiB bounds llama-server's prompt cache, which is what actually ate + // this box. Measured on homesrv 2026-08-03: the server's own default limit is + // 8192 MiB, it stores the full KV state of every idle slot it evicts (112 kiB + // per token, so 166 MiB for one 1521-token prompt), and RSS climbed by that + // much per distinct prompt until it hit 7.9 GB and half a gigabyte went to + // swap. Weights are only 1.1 GB and mmapped, and -ngl 99 costs almost no RSS + // because RADV keeps device memory outside the process. + // + // 0 ⇒ the flag is not passed and the server's own 8 GiB default applies. That + // is the escape hatch for a llama-server too old to know --cache-ram, not a + // recommendation. See docs/evals/2026-08-03-llama-prompt-cache.md. + CacheRAMMiB int + // ContextBlock renders the shared context block (who he is, how to // address him, the time) fresh for each turn. See internal/persona. // nil ⇒ no block, the prompts stand alone. @@ -116,6 +131,8 @@ func DefaultConfig(modelPath string) Config { Listen: "127.0.0.1:0", NGpuLayers: -1, NCtx: 2048, + // 512 MiB caps total RSS near 1 GB and still holds several recent prompts. + CacheRAMMiB: 512, Timeout: 30 * time.Second, } } @@ -225,8 +242,10 @@ func spawnLlamaServer(ctx context.Context, cfg Config) (backend, error) { return p, nil } -func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) { - p := &llamaProc{} +// llamaArgs is the command line for one resident server. It is a function and +// not an inline literal because kill-maven.sh's orphan sweep matches against +// this exact line, and a test pins the two together. +func llamaArgs(cfg Config) []string { args := []string{ "-m", cfg.ModelPath, "--host", "127.0.0.1", @@ -235,7 +254,15 @@ func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) { "-ngl", fmt.Sprintf("%d", cfg.NGpuLayers), "--no-webui", } - cmd := exec.CommandContext(ctx, cfg.BinPath, args...) + if cfg.CacheRAMMiB > 0 { + args = append(args, "--cache-ram", fmt.Sprintf("%d", cfg.CacheRAMMiB)) + } + return args +} + +func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) { + p := &llamaProc{} + cmd := exec.CommandContext(ctx, cfg.BinPath, llamaArgs(cfg)...) // Pdeathsig: the kernel SIGKILLs llama-server the moment mavend dies — by // ANY means, including SIGKILL/OOM/panic where our Close() never runs. Without // it a hard-killed mavend orphans its llama-server (reparented to init, keeps @@ -246,63 +273,104 @@ func startLlamaProc(ctx context.Context, cfg Config) (*llamaProc, error) { cmd.SysProcAttr = &syscall.SysProcAttr{Setpgid: true, Pdeathsig: syscall.SIGKILL} p.cmd = cmd - stderr, err := cmd.StderrPipe() + // One pipe for both streams. llama.cpp writes its buffer sizes, KV-cache + // layout and offload lines to stderr and its request log to stdout, and + // stdout used to go nowhere at all — so nothing about the model's memory was + // diagnosable from a running box. Both ends land in mavend's log now. + pr, pw, err := os.Pipe() if err != nil { - return nil, fmt.Errorf("llm: stderr pipe: %w", err) + return nil, fmt.Errorf("llm: output pipe: %w", err) } + cmd.Stdout = pw + cmd.Stderr = pw if err := cmd.Start(); err != nil { - stderr.Close() + pr.Close() + pw.Close() return nil, fmt.Errorf("llm: start: %w", err) } + // The child holds the only other reference to the write end. Dropping ours + // is what makes the reader see EOF when the child dies. + pw.Close() portCh := make(chan string, 1) errCh := make(chan error, 1) + tail := &lineTail{} p.wg.Add(1) go func() { defer p.wg.Done() - buf := make([]byte, 4096) - var leftover []byte - for { - n, err := stderr.Read(buf) - if n > 0 { - data := append(leftover, buf[:n]...) - lines := bytes.Split(data, []byte("\n")) - for _, line := range lines[:len(lines)-1] { - if m := listenRE.FindSubmatch(line); len(m) > 1 { - addr := string(m[1]) - portCh <- addr - close(portCh) - } + defer pr.Close() + sc := bufio.NewScanner(pr) + // llama.cpp prints one prompt per line and a prompt can be long. + sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) + listening := false + for sc.Scan() { + line := sc.Bytes() + log.Printf("llama: %s", line) + if !listening { + tail.add(string(line)) + if m := listenRE.FindSubmatch(line); len(m) > 1 { + listening = true + portCh <- string(m[1]) + close(portCh) } - leftover = lines[len(lines)-1] - } - if err != nil { - errCh <- err - return } } + err := sc.Err() + if err == nil { + err = io.EOF + } + errCh <- err }() + fail := func(err error) (*llamaProc, error) { + _ = cmd.Process.Kill() + _ = cmd.Wait() + return nil, err + } select { case addr := <-portCh: p.base = addr return p, nil case err := <-errCh: - _ = cmd.Process.Kill() - _ = cmd.Wait() - return nil, fmt.Errorf("llm: server output: %w", err) + // The tail is the whole diagnosis when the server dies during load: bare + // "EOF" never said which layer or which allocation it choked on. + return fail(fmt.Errorf("llm: server output: %w; last output: %s", err, tail.String())) case <-ctx.Done(): - _ = cmd.Process.Kill() - _ = cmd.Wait() - return nil, ctx.Err() + return fail(ctx.Err()) case <-time.After(60 * time.Second): - _ = cmd.Process.Kill() - _ = cmd.Wait() - return nil, fmt.Errorf("llm: server did not start within 60s") + return fail(fmt.Errorf("llm: server did not start within 60s; last output: %s", tail.String())) } } +// lineTail keeps the last few startup lines so a server that dies before it +// listens can say why in the error, not just "EOF". Written by the reader +// goroutine and read by whoever gives up on startup, so it takes a lock. +type lineTail struct { + mu sync.Mutex + lines []string +} + +const lineTailMax = 12 + +func (t *lineTail) add(line string) { + t.mu.Lock() + defer t.mu.Unlock() + t.lines = append(t.lines, line) + if len(t.lines) > lineTailMax { + t.lines = t.lines[len(t.lines)-lineTailMax:] + } +} + +func (t *lineTail) String() string { + t.mu.Lock() + defer t.mu.Unlock() + if len(t.lines) == 0 { + return "(no output)" + } + return strings.Join(t.lines, " | ") +} + // BaseURL is the llama-server this phraser talks to right now. It changes when // the model is swapped, so callers that cache it must register an observer // (OnSwap) rather than keeping the string forever. diff --git a/internal/phraser/spawn_test.go b/internal/phraser/spawn_test.go index 46182b6..636a7e9 100644 --- a/internal/phraser/spawn_test.go +++ b/internal/phraser/spawn_test.go @@ -1,9 +1,11 @@ package phraser import ( + "bytes" "context" "errors" "fmt" + "log" "os" "os/exec" "path/filepath" @@ -59,6 +61,19 @@ func TestExtractPort(t *testing.T) { } } +// The prompt cache is what ate 6.8GB of the deployed server's RSS, so the cap +// has to reach the command line, and the opt-out has to leave it off. +func TestLlamaArgsCapsPromptCache(t *testing.T) { + cfg := DefaultConfig("/m.gguf") + if got := strings.Join(llamaArgs(cfg), " "); !strings.Contains(got, "--cache-ram 512") { + t.Errorf("default args = %q, want --cache-ram 512", got) + } + cfg.CacheRAMMiB = 0 + if got := strings.Join(llamaArgs(cfg), " "); strings.Contains(got, "--cache-ram") { + t.Errorf("args with the cap off = %q, want no --cache-ram flag", got) + } +} + func TestStartLlamaProcScrapesPortAndReaps(t *testing.T) { bin := fakeLlama(t, listensThenSleeps) ctx, cancel := context.WithCancel(context.Background()) @@ -86,6 +101,48 @@ func TestStartLlamaProcScrapesPortAndReaps(t *testing.T) { } } +// captureLog redirects the standard logger for the duration of a test and +// returns what was written to it. +func captureLog(t *testing.T) *bytes.Buffer { + t.Helper() + var buf bytes.Buffer + old := log.Writer() + flags := log.Flags() + log.SetOutput(&buf) + log.SetFlags(0) + t.Cleanup(func() { log.SetOutput(old); log.SetFlags(flags) }) + return &buf +} + +// The child's buffer-size, KV-cache and offload lines are the only way to +// account for its memory on a running box, and they used to be dropped: stderr +// was scraped for the listen line and thrown away, stdout was never piped. +func TestStartLlamaProcForwardsChildOutput(t *testing.T) { + buf := captureLog(t) + bin := fakeLlama(t, `echo "load_tensors: Vulkan0 model buffer size = 1053.34 MiB" >&2 +echo "llama_context: KV self size = 448.00 MiB" +`+listensThenSleeps) + ctx, cancel := context.WithCancel(context.Background()) + defer cancel() + + p, err := startLlamaProc(ctx, testCfg(bin)) + if err != nil { + t.Fatalf("startLlamaProc: %v", err) + } + p.cancel = cancel + defer p.Close() + + got := buf.String() + for _, want := range []string{ + "llama: load_tensors: Vulkan0 model buffer size = 1053.34 MiB", // stderr + "llama: llama_context: KV self size = 448.00 MiB", // stdout, previously discarded + } { + if !strings.Contains(got, want) { + t.Errorf("log missing %q\nlog was:\n%s", want, got) + } + } +} + func TestStartLlamaProcFailureArms(t *testing.T) { t.Run("binary missing", func(t *testing.T) { cfg := testCfg(filepath.Join(t.TempDir(), "does-not-exist")) @@ -96,13 +153,18 @@ func TestStartLlamaProcFailureArms(t *testing.T) { }) t.Run("server exits without listening", func(t *testing.T) { - // stderr closes, so the reader goroutine reports EOF on errCh. + // stderr closes, so the reader goroutine reports EOF on errCh. The error + // must carry the child's last words: bare "EOF" named no cause. + captureLog(t) bin := fakeLlama(t, `echo "ggml_vulkan: no device" >&2 exit 1`) _, err := startLlamaProc(context.Background(), testCfg(bin)) if err == nil || !strings.Contains(err.Error(), "llm: server output") { t.Fatalf("err = %v, want the server-output arm", err) } + if !strings.Contains(err.Error(), "ggml_vulkan: no device") { + t.Errorf("err = %v, want the child's last output in it", err) + } }) t.Run("context cancelled during startup", func(t *testing.T) { @@ -241,15 +303,7 @@ func TestKillMavenScriptMatchesRealCommandLine(t *testing.T) { // startLlamaProc that breaks the sweep fails here instead of on the box. cfg := DefaultConfig("/opt/maven/models/llm/Qwen3-1.7B-UD-Q4_K_XL.gguf") cfg.NCtx, cfg.NGpuLayers = 4096, 99 - cmdline := strings.Join([]string{ - cfg.BinPath, - "-m", cfg.ModelPath, - "--host", "127.0.0.1", - "--port", extractPort(cfg.Listen), - "-c", fmt.Sprintf("%d", cfg.NCtx), - "-ngl", fmt.Sprintf("%d", cfg.NGpuLayers), - "--no-webui", - }, " ") + cmdline := cfg.BinPath + " " + strings.Join(llamaArgs(cfg), " ") if !pat.MatchString(cmdline) { t.Fatalf("kill-maven.sh pattern %q does not match %q — orphans would leak", m[1], cmdline) } From f9b2391a8b5374ad67dc05bdd1b368ff4e9ee48d Mon Sep 17 00:00:00 2001 From: claude Date: Mon, 3 Aug 2026 23:19:15 +0400 Subject: [PATCH 2/3] phraser: cap llama-server's prompt cache at 512 MiB (V-499) The forwarded log named the cause in one line: the prompt cache limit defaults to 8192 MiB. llama-server saves the full KV state of every idle slot it evicts, 112 kiB per token, so RSS climbed about 170MB per distinct prompt until the deployed server held 7.9GB for a 1.1GB model. Measured on homesrv today, uncapped versus `--cache-ram 512`: RSS plateaus at 932MB from the fourth distinct prompt instead of climbing. The task's leading guess was wrong. `-ngl 99` costs almost no RSS, because RADV keeps device memory outside the process. Numbers and method in docs/evals/2026-08-03-llama-prompt-cache.md. `-c 4096` is untouched. The knob is `phraser.cache_ram_mib`, unset means 512, negative passes no flag for a llama-server too old to know it. The deploy still runs the old image, so the box keeps its 8 GiB default until mavend is rebuilt. Co-Authored-By: Claude Opus 5 --- cmd/mavend/main.go | 18 +++++ deploy/mavend.json | 1 + docs/evals/2026-08-03-llama-prompt-cache.md | 77 +++++++++++++++++++++ internal/config/config.go | 6 ++ internal/phraser/llmphraser.go | 2 +- 5 files changed, 103 insertions(+), 1 deletion(-) create mode 100644 docs/evals/2026-08-03-llama-prompt-cache.md diff --git a/cmd/mavend/main.go b/cmd/mavend/main.go index 892330d..05d23f8 100644 --- a/cmd/mavend/main.go +++ b/cmd/mavend/main.go @@ -251,6 +251,7 @@ func run(args []string) error { Listen: cfg.Phraser.Listen, NGpuLayers: cfg.Phraser.NGpuLayers, NCtx: cfg.Phraser.NCtx, + CacheRAMMiB: cacheRAMMiB(cfg.Phraser.CacheRAMMiB), Timeout: time.Duration(cfg.Phraser.Timeout), LLMNudges: cfg.Phraser.LLMNudges, ContextBlock: contextBlockFn(cfg, time.Now), @@ -525,6 +526,7 @@ func run(args []string) error { Listen: cfg.Phraser.Listen, NGpuLayers: cfg.Phraser.NGpuLayers, NCtx: cfg.Phraser.NCtx, + CacheRAMMiB: cacheRAMMiB(cfg.Phraser.CacheRAMMiB), Timeout: time.Duration(cfg.Phraser.Timeout), LLMNudges: cfg.Phraser.LLMNudges, ContextBlock: contextBlockFn(cfg, time.Now), @@ -788,6 +790,22 @@ func personaFacts(cfg *config.Config) persona.Facts { return f } +// cacheRAMMiB resolves phraser.cache_ram_mib into the phraser's field. Unset +// means 512 MiB and not "whatever the server does", because the server's own +// default is 8 GiB of prompt cache and that is what put 7.9 GB of RSS and half +// a gigabyte of swap on homesrv for a 1.1 GB model. A negative value is the +// deliberate opt-out: no flag is passed, the server's default applies, and the +// operator owns the consequence. +func cacheRAMMiB(configured int) int { + if configured == 0 { + return 512 + } + if configured < 0 { + return 0 + } + return configured +} + // contextBlockFn returns the per-turn renderer of the shared context block. // Per turn, not once at startup, because the block states the current time. func contextBlockFn(cfg *config.Config, now func() time.Time) func() string { diff --git a/deploy/mavend.json b/deploy/mavend.json index 3a3ee02..bb67b34 100644 --- a/deploy/mavend.json +++ b/deploy/mavend.json @@ -20,6 +20,7 @@ "bin_path": "llama-server", "n_gpu_layers": 99, "n_ctx": 4096, + "cache_ram_mib": 512, "timeout": "60s", "llm_nudges": false }, diff --git a/docs/evals/2026-08-03-llama-prompt-cache.md b/docs/evals/2026-08-03-llama-prompt-cache.md new file mode 100644 index 0000000..1a7c48d --- /dev/null +++ b/docs/evals/2026-08-03-llama-prompt-cache.md @@ -0,0 +1,77 @@ +# Where the resident model's 7.9GB of RSS goes (2026-08-03, homesrv) + +Measured for Vikunja #499. The deployed llama-server held 7.9GB RSS for a 1.1GB +model file. Half a gigabyte of it was in swap, on a box that also runs +whisper.cpp, piper and the embedder. + +## Method + +`maven-mavend-1` was stopped for the measurement, with the owner's approval. +Its own binary then ran on the host with the exact deployed command line. That +binary is `/opt/maven/bin/llama-server`, version `1 (4c65955)`, a Vulkan build. + +```sh +llama-server -m /mnt/hdd1/llms/qwen3/Qwen3-1.7B-UD-Q4_K_XL.gguf \ + --host 127.0.0.1 --port 18099 -c 4096 -ngl 99 --no-webui +``` + +RSS was read from `/proc//status` after load and after each of 8 distinct +1521-token prompts. `smaps` of the deployed process was read first, from inside +the container, since the host user cannot read another user's maps. + +## The cause: the prompt cache, not the weights and not the offload + +The startup log says it outright: + +```text +srv load_model: prompt cache is enabled, size limit: 8192 MiB +srv llama_server: n_parallel is set to auto, using n_parallel = 4 and kv_unified = true +``` + +The server saves the full KV state of every idle slot it evicts. It keeps up to +8GiB of those states in host RAM (llama.cpp PR 16391). One saved prompt of 1521 +tokens costs 166.377 MiB. That is 112 kiB per token, exactly Qwen3-1.7B's KV +footprint (28 layers x 2 x 1024 dims x 2 bytes). + +RSS at rest, and per distinct prompt: + +| Prompts served | RSS, default | RSS, `--cache-ram 512` | +|---|---|---| +| 0 (just loaded) | 443 MB | 411 MB | +| 1 | 445 MB | 411 MB | +| 4 | 958 MB | 929 MB | +| 8 | 1641 MB | 932 MB | + +Uncapped, RSS climbs about 170MB per distinct prompt and does not stop until +the 8GiB limit. Capped at 512 MiB it plateaus at 932MB from the fourth prompt +on, with the cache holding steady at `3 prompts, 499.132 MiB` and evicting. + +The 7.9GB on the running daemon was that climb, weeks of it. Its `smaps` showed +one 6.03GB anonymous mapping at 5.32GB resident plus a 1.45GB mapping at 1.27GB +resident, and only 30MB of file-backed RSS. + +## The task's leading guess was wrong + +`-ngl 99` on the Vega iGPU costs almost no process RSS. A freshly loaded server +has 95MB of anonymous RSS in total. RADV allocates device memory through the +kernel, outside the process, and the log sees 8202 MiB free on `Vulkan0`. The +weights are mmapped and file-backed, so they are evictable and do not pin RSS. The logit buffer is not visible in the numbers above at all. + +## Decision + +`--cache-ram 512` is now the default, wired as `phraser.cache_ram_mib` and set +in `deploy/mavend.json`. 512 MiB caps total RSS near 1GB, an eighth of what the +box carried. It still holds three of the 1521-token probes above. Maven's real +routing and phrasing prompts are much shorter, so it holds more of those than +the table suggests. `-c 4096` is untouched, as #499 +required. A negative `cache_ram_mib` passes no flag, for a llama-server too old +to know it. + +Not changed: `n_parallel = 4`. With `kv_unified = true` the four slots share one +4096-token KV cache, so they do not multiply it. + +The other half of #499 was that none of these lines were reachable. mavend +scraped llama-server's stderr for the listen line and discarded it, and never +piped stdout at all. Both streams now go to mavend's log with a `llama:` prefix. +The last 12 startup lines go into the error when the server dies before it +listens. diff --git a/internal/config/config.go b/internal/config/config.go index c34d8c2..ff72b31 100644 --- a/internal/config/config.go +++ b/internal/config/config.go @@ -1276,6 +1276,12 @@ type PhraserConfig struct { NCtx int `json:"n_ctx,omitempty"` Timeout Duration `json:"timeout,omitempty"` + // CacheRAMMiB bounds llama-server's prompt cache. Omitted ⇒ 512 MiB, which + // is what keeps the resident model near 1 GB of RSS instead of the 7.9 GB + // measured on 2026-08-03. Set it to -1 to pass no flag at all and let the + // server apply its own 8 GiB default. See phraser.Config.CacheRAMMiB. + CacheRAMMiB int `json:"cache_ram_mib,omitempty"` + // LLMNudges — let the model word nudges again. Off by default: nudges are // worded from hand-written Russian templates now (the model broke the // persona and invented units). Chat, query and reminder phrasing always go diff --git a/internal/phraser/llmphraser.go b/internal/phraser/llmphraser.go index d0e79bf..2c5e28d 100644 --- a/internal/phraser/llmphraser.go +++ b/internal/phraser/llmphraser.go @@ -133,7 +133,7 @@ func DefaultConfig(modelPath string) Config { NCtx: 2048, // 512 MiB caps total RSS near 1 GB and still holds several recent prompts. CacheRAMMiB: 512, - Timeout: 30 * time.Second, + Timeout: 30 * time.Second, } } From 58051b5af1914790a2daeafcff9ca3e64a6e91ce Mon Sep 17 00:00:00 2001 From: claude Date: Mon, 3 Aug 2026 23:28:36 +0400 Subject: [PATCH 3/3] docs: record the #499 deploy (V-499) --- docs/evals/2026-08-03-llama-prompt-cache.md | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/docs/evals/2026-08-03-llama-prompt-cache.md b/docs/evals/2026-08-03-llama-prompt-cache.md index 1a7c48d..70d6436 100644 --- a/docs/evals/2026-08-03-llama-prompt-cache.md +++ b/docs/evals/2026-08-03-llama-prompt-cache.md @@ -75,3 +75,10 @@ scraped llama-server's stderr for the listen line and discarded it, and never piped stdout at all. Both streams now go to mavend's log with a `llama:` prefix. The last 12 startup lines go into the error when the server dies before it listens. + +## Deployed + +The `mavenai:latest` image was rebuilt and `maven-mavend-1` recreated the same +day. The daemon's own log now carries the child's startup, it reads +`prompt cache is enabled, size limit: 512 MiB`, and the resident server sat at +439MB RSS after load and 613MB after one served turn.