Merge pull request 'Task/495 bug x escapes the personal boundary and' (#104) from task/495-bug-x-escapes-the-personal-boundary-and into master

Reviewed-on: #104

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 {

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
   },

docs/evals/2026-08-03-llama-prompt-cache.md

@@ -0,0 +1,84 @@
+# 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/<pid>/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.
+
+## 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.

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

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,7 +131,9 @@ func DefaultConfig(modelPath string) Config {
 		Listen:     "127.0.0.1:0",
 		NGpuLayers: -1,
 		NCtx:       2048,
-		Timeout:    30 * time.Second,
+		// 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.

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)
 	}