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