Eval bug: gpt-oss model reprocess the entire prompt from beginning.

[narendrachaudhary51]

Name and Version

I am running on a Emerald Rapids Xeon CPU socket with the following command. Commit id of code is - c252ce6. This is a recent commit.

numactl -m 0 -C 0-59 llama-server --cpu-range 0-59 -m /cold_storage/ml_datasets/narendra/llama.cpp_models/gpt-oss/ggml-org_gpt-oss-120b-GGUF_gpt-oss-120b-mxfp4.gguf -t 60 --port 10000 --cont-batching --parallel 8 --ctx-size 65536 --numa numactl --reasoning-format none --jinja --mlock -fa auto --no-mmap --cache-reuse 256 --swa-checkpoints 10

This is the server log for gpt-oss 120b. As you can see n_prompt_tokens goes from 86, 1916, 5877 in three queries and n_tokens=n_prompt_tokens which is also 86, 1916, 5877

---

srv update_slots: all slots are idle
srv params_from: Chat format: GPT-OSS
slot launch_slot_: id 3 | task 12914 | processing task
slot update_slots: id 3 | task 12914 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 86
slot update_slots: id 3 | task 12914 | kv cache rm [0, end)
slot update_slots: id 3 | task 12914 | prompt processing progress, n_past = 86, n_tokens = 86, progress = 1.000000
slot update_slots: id 3 | task 12914 | prompt done, n_past = 86, n_tokens = 86
slot update_slots: id 3 | task 12914 | SWA checkpoint create, pos_min = 0, pos_max = 85, size = 3.025 MiB, total = 1/10 (3.025 MiB)
slot release: id 3 | task 12914 | stop processing: n_past = 1967, truncated = 0
slot print_timing: id 3 | task 12914 |
prompt eval time = 474.41 ms / 86 tokens ( 5.52 ms per token, 181.28 tokens per second)
eval time = 48978.99 ms / 1882 tokens ( 26.02 ms per token, 38.42 tokens per second)
total time = 49453.39 ms / 1968 tokens
srv log_server_r: request: POST /v1/chat/completions 127.0.0.1 200
srv update_slots: all slots are idle
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 2 | task 14797 | processing task
slot update_slots: id 2 | task 14797 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 1916
slot update_slots: id 2 | task 14797 | kv cache rm [0, end)
slot update_slots: id 2 | task 14797 | prompt processing progress, n_past = 1916, n_tokens = 1916, progress = 1.000000
slot update_slots: id 2 | task 14797 | prompt done, n_past = 1916, n_tokens = 1916
slot update_slots: id 2 | task 14797 | SWA checkpoint create, pos_min = 1148, pos_max = 1915, size = 27.009 MiB, total = 1/10 (27.009 MiB)
slot release: id 2 | task 14797 | stop processing: n_past = 6010, truncated = 0
slot print_timing: id 2 | task 14797 |
prompt eval time = 10853.30 ms / 1916 tokens ( 5.66 ms per token, 176.54 tokens per second)
eval time = 125051.40 ms / 4095 tokens ( 30.54 ms per token, 32.75 tokens per second)
total time = 135904.70 ms / 6011 tokens
srv log_server_r: request: POST /v1/chat/completions 127.0.0.1 200
srv update_slots: all slots are idle
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 1 | task 18893 | processing task
slot update_slots: id 1 | task 18893 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 5877
slot update_slots: id 1 | task 18893 | kv cache rm [0, end)
slot update_slots: id 1 | task 18893 | prompt processing progress, n_past = 2048, n_tokens = 2048, progress = 0.348477
slot update_slots: id 1 | task 18893 | kv cache rm [2048, end)
slot update_slots: id 1 | task 18893 | prompt processing progress, n_past = 4096, n_tokens = 2048, progress = 0.696954
slot update_slots: id 1 | task 18893 | kv cache rm [4096, end)
slot update_slots: id 1 | task 18893 | prompt processing progress, n_past = 5877, n_tokens = 1781, progress = 1.000000
slot update_slots: id 1 | task 18893 | prompt done, n_past = 5877, n_tokens = 1781
slot update_slots: id 1 | task 18893 | SWA checkpoint create, pos_min = 5109, pos_max = 5876, size = 27.009 MiB, total = 1/10 (27.009 MiB)
slot release: id 1 | task 18893 | stop processing: n_past = 8191, truncated = 0
slot print_timing: id 1 | task 18893 |
prompt eval time = 41512.46 ms / 5877 tokens ( 7.06 ms per token, 141.57 tokens per second)
eval time = 84743.58 ms / 2315 tokens ( 36.61 ms per token, 27.32 tokens per second)
total time = 126256.05 ms / 8192 tokens
srv log_server_r: request: POST /v1/chat/completions 127.0.0.1 200
srv update_slots: all slots are idle_

In comparison for qwen3 model (235b-a22)
n_tokens is not equal to n_prompt_tokens

srv update_slots: all slots are idle
srv log_server_r: request: GET / 10.67.162.84 200
srv log_server_r: request: GET /props 10.67.162.84 200
srv params_from: Chat format: Hermes 2 Pro
slot launch_slot_: id 7 | task 0 | processing task
slot update_slots: id 7 | task 0 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 15
slot update_slots: id 7 | task 0 | kv cache rm [0, end)
slot update_slots: id 7 | task 0 | prompt processing progress, n_past = 15, n_tokens = 15, progress = 1.000000
slot update_slots: id 7 | task 0 | prompt done, n_past = 15, n_tokens = 15
slot release: id 7 | task 0 | stop processing: n_past = 851, truncated = 0
slot print_timing: id 7 | task 0 |
prompt eval time = 426.47 ms / 15 tokens ( 28.43 ms per token, 35.17 tokens per second)
eval time = 73571.96 ms / 837 tokens ( 87.90 ms per token, 11.38 tokens per second)
total time = 73998.42 ms / 852 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.67.162.84 200
srv params_from_: Chat format: Hermes 2 Pro
slot launch_slot_: id 7 | task 838 | processing task
slot update_slots: id 7 | task 838 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 867
slot update_slots: id 7 | task 838 | kv cache rm [577, end)
slot update_slots: id 7 | task 838 | prompt processing progress, n_past = 867, n_tokens = 290, progress = 0.334487
slot update_slots: id 7 | task 838 | prompt done, n_past = 867, n_tokens = 290
slot release: id 7 | task 838 | stop processing: n_past = 2053, truncated = 0
slot print_timing: id 7 | task 838 |
prompt eval time = 5860.13 ms / 290 tokens ( 20.21 ms per token, 49.49 tokens per second)
eval time = 122713.46 ms / 1187 tokens ( 103.38 ms per token, 9.67 tokens per second)
total time = 128573.58 ms / 1477 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.67.162.84 200
srv params_from_: Chat format: Hermes 2 Pro
slot launch_slot_: id 7 | task 2026 | processing task
slot update_slots: id 7 | task 2026 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 2070
slot update_slots: id 7 | task 2026 | kv cache rm [2053, end)
slot update_slots: id 7 | task 2026 | prompt processing progress, n_past = 2070, n_tokens = 17, progress = 0.008213
slot update_slots: id 7 | task 2026 | prompt done, n_past = 2070, n_tokens = 17
slot release: id 7 | task 2026 | stop processing: n_past = 3634, truncated = 0
slot print_timing: id 7 | task 2026 |
prompt eval time = 828.94 ms / 17 tokens ( 48.76 ms per token, 20.51 tokens per second)
eval time = 198837.40 ms / 1565 tokens ( 127.05 ms per token, 7.87 tokens per second)
total time = 199666.34 ms / 1582 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.67.162.84 200
srv params_from_: Chat format: Hermes 2 Pro
slot launch_slot_: id 7 | task 3592 | processing task
slot update_slots: id 7 | task 3592 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 3651
slot update_slots: id 7 | task 3592 | kv cache rm [3634, end)
slot update_slots: id 7 | task 3592 | prompt processing progress, n_past = 3651, n_tokens = 17, progress = 0.004656
slot update_slots: id 7 | task 3592 | prompt done, n_past = 3651, n_tokens = 17
slot release: id 7 | task 3592 | stop processing: n_past = 5185, truncated = 0
slot print_timing: id 7 | task 3592 |
prompt eval time = 945.71 ms / 17 tokens ( 55.63 ms per token, 17.98 tokens per second)
eval time = 230112.39 ms / 1535 tokens ( 149.91 ms per token, 6.67 tokens per second)
total time = 231058.10 ms / 1552 tokens
srv update_slots: all slots are idle_

This issue really kills the user experience for second or third query onwards.

Operating systems

Linux

GGML backends

CPU

Hardware

INTEL(R) XEON(R) PLATINUM 8580 (60 cores) (Emerald Rapids)

Models

gpt-oss 120b

Problem description & steps to reproduce

numactl -m 0 -C 0-59 llama-server --cpu-range 0-59 -m /cold_storage/ml_datasets/narendra/llama.cpp_models/gpt-oss/ggml-org_gpt-oss-120b-GGUF_gpt-oss-120b-mxfp4.gguf -t 60 --port 10000 --cont-batching --parallel 8 --ctx-size 65536 --numa numactl --reasoning-format none --jinja --mlock -fa auto --no-mmap --cache-reuse 256 --swa-checkpoints 10

Run three prompts. They can be anything. three examples below

• Describe intel as a company
• Describe AMD as a company
• Describe Apple as a company

First Bad Commit

No response

Relevant log output

srv update_slots: all slots are idle
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 3 | task 12914 | processing task
slot update_slots: id 3 | task 12914 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 86
slot update_slots: id 3 | task 12914 | kv cache rm [0, end)
slot update_slots: id 3 | task 12914 | prompt processing progress, n_past = 86, n_tokens = 86, progress = 1.000000
slot update_slots: id 3 | task 12914 | prompt done, n_past = 86, n_tokens = 86
slot update_slots: id 3 | task 12914 | SWA checkpoint create, pos_min = 0, pos_max = 85, size = 3.025 MiB, total = 1/10 (3.025 MiB)
slot release: id 3 | task 12914 | stop processing: n_past = 1967, truncated = 0
slot print_timing: id 3 | task 12914 |
prompt eval time = 474.41 ms / 86 tokens ( 5.52 ms per token, 181.28 tokens per second)
eval time = 48978.99 ms / 1882 tokens ( 26.02 ms per token, 38.42 tokens per second)
total time = 49453.39 ms / 1968 tokens
srv log_server_r: request: POST /v1/chat/completions 127.0.0.1 200
srv update_slots: all slots are idle
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 2 | task 14797 | processing task
slot update_slots: id 2 | task 14797 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 1916
slot update_slots: id 2 | task 14797 | kv cache rm [0, end)
slot update_slots: id 2 | task 14797 | prompt processing progress, n_past = 1916, n_tokens = 1916, progress = 1.000000
slot update_slots: id 2 | task 14797 | prompt done, n_past = 1916, n_tokens = 1916
slot update_slots: id 2 | task 14797 | SWA checkpoint create, pos_min = 1148, pos_max = 1915, size = 27.009 MiB, total = 1/10 (27.009 MiB)
slot release: id 2 | task 14797 | stop processing: n_past = 6010, truncated = 0
slot print_timing: id 2 | task 14797 |
prompt eval time = 10853.30 ms / 1916 tokens ( 5.66 ms per token, 176.54 tokens per second)
eval time = 125051.40 ms / 4095 tokens ( 30.54 ms per token, 32.75 tokens per second)
total time = 135904.70 ms / 6011 tokens
srv log_server_r: request: POST /v1/chat/completions 127.0.0.1 200
srv update_slots: all slots are idle
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 1 | task 18893 | processing task
slot update_slots: id 1 | task 18893 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 5877
slot update_slots: id 1 | task 18893 | kv cache rm [0, end)
slot update_slots: id 1 | task 18893 | prompt processing progress, n_past = 2048, n_tokens = 2048, progress = 0.348477
slot update_slots: id 1 | task 18893 | kv cache rm [2048, end)
slot update_slots: id 1 | task 18893 | prompt processing progress, n_past = 4096, n_tokens = 2048, progress = 0.696954
slot update_slots: id 1 | task 18893 | kv cache rm [4096, end)
slot update_slots: id 1 | task 18893 | prompt processing progress, n_past = 5877, n_tokens = 1781, progress = 1.000000
slot update_slots: id 1 | task 18893 | prompt done, n_past = 5877, n_tokens = 1781
slot update_slots: id 1 | task 18893 | SWA checkpoint create, pos_min = 5109, pos_max = 5876, size = 27.009 MiB, total = 1/10 (27.009 MiB)
slot release: id 1 | task 18893 | stop processing: n_past = 8191, truncated = 0
slot print_timing: id 1 | task 18893 |
prompt eval time = 41512.46 ms / 5877 tokens ( 7.06 ms per token, 141.57 tokens per second)
eval time = 84743.58 ms / 2315 tokens ( 36.61 ms per token, 27.32 tokens per second)
total time = 126256.05 ms / 8192 tokens
srv log_server_r: request: POST /v1/chat/completions 127.0.0.1 200
srv update_slots: all slots are idle

[pwilkin]

Can you see if you can reproduce this problem:

1. with --swa-full
2. with --reasoning-format auto
3. with --cache-reuse 0
   ?

[narendrachaudhary51]

@pwilkin This is the output after I use settings suggested by you. I am still seeing that, whole prompt is getting reprocessed.

srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 7 | task 0 | processing task
slot update_slots: id 7 | task 0 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 86
slot update_slots: id 7 | task 0 | kv cache rm [0, end)
slot update_slots: id 7 | task 0 | prompt processing progress, n_past = 86, n_tokens = 86, progress = 1.000000
slot update_slots: id 7 | task 0 | prompt done, n_past = 86, n_tokens = 86
slot release: id 7 | task 0 | stop processing: n_past = 1505, truncated = 0
slot print_timing: id 7 | task 0 |
prompt eval time = 573.54 ms / 86 tokens ( 6.67 ms per token, 149.95 tokens per second)
eval time = 37761.63 ms / 1420 tokens ( 26.59 ms per token, 37.60 tokens per second)
total time = 38335.18 ms / 1506 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.67.162.84 200
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 6 | task 1421 | processing task
slot update_slots: id 6 | task 1421 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 1446
slot update_slots: id 6 | task 1421 | kv cache rm [0, end)
slot update_slots: id 6 | task 1421 | prompt processing progress, n_past = 1446, n_tokens = 1446, progress = 1.000000
slot update_slots: id 6 | task 1421 | prompt done, n_past = 1446, n_tokens = 1446
slot release: id 6 | task 1421 | stop processing: n_past = 3158, truncated = 0
slot print_timing: id 6 | task 1421 |
prompt eval time = 8660.72 ms / 1446 tokens ( 5.99 ms per token, 166.96 tokens per second)
eval time = 56003.66 ms / 1713 tokens ( 32.69 ms per token, 30.59 tokens per second)
total time = 64664.37 ms / 3159 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.67.162.84 200
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 5 | task 3135 | processing task
slot update_slots: id 5 | task 3135 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 3116
slot update_slots: id 5 | task 3135 | kv cache rm [0, end)
slot update_slots: id 5 | task 3135 | prompt processing progress, n_past = 2048, n_tokens = 2048, progress = 0.657253
slot update_slots: id 5 | task 3135 | kv cache rm [2048, end)
slot update_slots: id 5 | task 3135 | prompt processing progress, n_past = 3116, n_tokens = 1068, progress = 1.000000
slot update_slots: id 5 | task 3135 | prompt done, n_past = 3116, n_tokens = 1068
slot release: id 5 | task 3135 | stop processing: n_past = 5278, truncated = 0
slot print_timing: id 5 | task 3135 |
prompt eval time = 24250.97 ms / 3116 tokens ( 7.78 ms per token, 128.49 tokens per second)
eval time = 85953.22 ms / 2163 tokens ( 39.74 ms per token, 25.16 tokens per second)
total time = 110204.19 ms / 5279 tokens
srv update_slots: all slots are idle

[ggerganov]

The problem is that the server decides to assign each new request to a new slot instead of reusing the last one based on similarity. Looks like the prompt similarity mechanism does not kick in for your example because the responses are longer than the full previous context and the default prompt similarity threshold of 0.5 is not enough.

Try to reduce the threshold, for example by adding -sps 0.1. No need to change anything else in your original command. Even increasing the SWA checkpoints is not necessary.

[narendrachaudhary51]

@ggerganov -sps 0.1 seems to be solving the issue. Thank you for helping.
Perhaps, threshold of 0.5 is too large a value for LLMs that provide long outputs and llama.cpp could consider making 0.1 or 0.2 as default.

---

srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 7 | task 0 | processing task
slot update_slots: id 7 | task 0 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 86
slot update_slots: id 7 | task 0 | kv cache rm [0, end)
slot update_slots: id 7 | task 0 | prompt processing progress, n_past = 86, n_tokens = 86, progress = 1.000000
slot update_slots: id 7 | task 0 | prompt done, n_past = 86, n_tokens = 86
slot update_slots: id 7 | task 0 | SWA checkpoint create, pos_min = 0, pos_max = 85, size = 3.025 MiB, total = 1/10 (3.025 MiB)
slot release: id 7 | task 0 | stop processing: n_past = 1486, truncated = 0
slot print_timing: id 7 | task 0 |
prompt eval time = 606.04 ms / 86 tokens ( 7.05 ms per token, 141.91 tokens per second)
eval time = 35120.41 ms / 1401 tokens ( 25.07 ms per token, 39.89 tokens per second)
total time = 35726.45 ms / 1487 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.247.151.13 200
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 6 | task 1402 | processing task
slot update_slots: id 6 | task 1402 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 1438
slot update_slots: id 6 | task 1402 | kv cache rm [0, end)
slot update_slots: id 6 | task 1402 | prompt processing progress, n_past = 1438, n_tokens = 1438, progress = 1.000000
slot update_slots: id 6 | task 1402 | prompt done, n_past = 1438, n_tokens = 1438
slot update_slots: id 6 | task 1402 | SWA checkpoint create, pos_min = 670, pos_max = 1437, size = 27.009 MiB, total = 1/10 (27.009 MiB)
slot release: id 6 | task 1402 | stop processing: n_past = 3309, truncated = 0
slot print_timing: id 6 | task 1402 |
prompt eval time = 7551.92 ms / 1438 tokens ( 5.25 ms per token, 190.42 tokens per second)
eval time = 52033.18 ms / 1872 tokens ( 27.80 ms per token, 35.98 tokens per second)
total time = 59585.09 ms / 3310 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.247.151.13 200
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 6 | task 3275 | processing task
slot update_slots: id 6 | task 3275 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 3253
slot update_slots: id 6 | task 3275 | n_past = 1438, cache_tokens.size() = 3309, seq_id = 6, pos_min = 2541, n_swa = 128
slot update_slots: id 6 | task 3275 | SWA checkpoint restore, pos_min = 670, pos_max = 1437, size = 27.009 MiB
slot update_slots: id 6 | task 3275 | kv cache rm [1437, end)
slot update_slots: id 6 | task 3275 | prompt processing progress, n_past = 3253, n_tokens = 1816, progress = 0.558254
slot update_slots: id 6 | task 3275 | prompt done, n_past = 3253, n_tokens = 1816
slot update_slots: id 6 | task 3275 | SWA checkpoint create, pos_min = 2485, pos_max = 3252, size = 27.009 MiB, total = 2/10 (54.018 MiB)
slot release: id 6 | task 3275 | stop processing: n_past = 5242, truncated = 0
slot print_timing: id 6 | task 3275 |
prompt eval time = 12380.87 ms / 1816 tokens ( 6.82 ms per token, 146.68 tokens per second)
eval time = 61704.79 ms / 1990 tokens ( 31.01 ms per token, 32.25 tokens per second)
total time = 74085.66 ms / 3806 tokens
srv update_slots: all slots are idle
srv log_server_r: request: POST /v1/chat/completions 10.247.151.13 200
srv params_from_: Chat format: GPT-OSS
slot launch_slot_: id 6 | task 5266 | processing task
slot update_slots: id 6 | task 5266 | new prompt, n_ctx_slot = 8192, n_keep = 0, n_prompt_tokens = 5176
slot update_slots: id 6 | task 5266 | n_past = 3253, cache_tokens.size() = 5242, seq_id = 6, pos_min = 4474, n_swa = 128
slot update_slots: id 6 | task 5266 | SWA checkpoint restore, pos_min = 2485, pos_max = 3252, size = 27.009 MiB
slot update_slots: id 6 | task 5266 | kv cache rm [3252, end)
slot update_slots: id 6 | task 5266 | prompt processing progress, n_past = 5176, n_tokens = 1924, progress = 0.371716
slot update_slots: id 6 | task 5266 | prompt done, n_past = 5176, n_tokens = 1924
slot update_slots: id 6 | task 5266 | SWA checkpoint create, pos_min = 4408, pos_max = 5175, size = 27.009 MiB, total = 3/10 (81.028 MiB)
slot release: id 6 | task 5266 | stop processing: n_past = 7240, truncated = 0
slot print_timing: id 6 | task 5266 |
prompt eval time = 15685.28 ms / 1924 tokens ( 8.15 ms per token, 122.66 tokens per second)
eval time = 72181.31 ms / 2065 tokens ( 34.95 ms per token, 28.61 tokens per second)
total time = 87866.60 ms / 3989 tokens
srv update_slots: all slots are idle

[ggerganov]

Perhaps, threshold of 0.5 is too large a value for LLMs that provide long outputs and llama.cpp could consider making 0.1 or 0.2 as default.

Yes, I agree. Prepared a change to address this: #15913