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..70d6436 --- /dev/null +++ b/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//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. 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 67970c9..2c5e28d 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,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. 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) }