Misc. bug: 3x Slower prompt processing on chat completion

[EugeoSynthesisThirtyTwo]

Name and Version

version: 9864 (b5315e1)
built with MSVC 19.51.36248.0 for x64

Operating systems

Windows

Which llama.cpp modules do you know to be affected?

llama-server

Command line

llama-server.exe -m DeepSeek-V4-Flash-MXFP4-00001-of-00004.gguf -a Deepseek-V4-Flash --port 5001 -c 262144 --host 0.0.0.0 -fa on --threads 16 -np 1 --n-gpu-layers 99 --no-mmap --swa-checkpoints 32 --checkpoint-min-step 2048 -ub 2048 -b 2048 -ot "\.(0|1|2|3|4|5)\.ffn_(gate|up|down)_exps.=CUDA0,\.(6|7|8|9|10|11)\.ffn_(gate|up|down)_exps.=CUDA1,\.*\.ffn_(gate|up|down)_exps.=CPU"

Problem description & steps to reproduce

The prompt processing is done in small chunks instead of the requested 2048 chunks (-ub 2048 -b 2048), resulting in a 3x slowdown in prompt processing (8:09 instead of 2:43). See the logs for details.

I strongly suspect that:

1. a chunk corresponds to a pair [user query, assistant reply]. Indeed, my chat is 284 messages long (142 user messages, 142 assistant replies, and a few system prompts), and there are 147 chunks being processed.
2. the purpose of processing the prompt in chunks is for checkpoint creation

However:

1. there is no need to chunk the first 109 messages, because I have a maximum of 32 checkpoints created. (--swa-checkpoints 32)
2. messages can be grouped to add up to 2048 tokens (--checkpoint-min-step 2048)

To reproduce, send a chat completion request. Your chat history must include lots of small messages. For instance

{
  messages: [
    {role: 'system', content: 'a'},
    {role: 'user', content: 'b'},
    {role: 'assistant', content: 'c'},
    {role: 'user', content: 'd'},
    {role: 'assistant', content: 'e'},
    {role: 'user', content: 'f'},
    {role: 'assistant', content: 'g'},
    {role: 'user', content: 'h'},
    {role: 'assistant', content: 'i'},
    {role: 'user', content: 'j'},
    {role: 'assistant', content: 'k'},
    {role: 'user', content: 'l'},
    {role: 'assistant', content: 'm'},
    {role: 'user', content: 'n'},
    {role: 'assistant', content: 'o'},
    {role: 'user', content: 'p'},
    {role: 'assistant', content: 'k'},
    {role: 'user', content: 'r'},
    {role: 'assistant', content: 's'},
    {role: 'user', content: 't'},
    {role: 'assistant', content: 'u'},
    {role: 'user', content: 'v'},
    {role: 'assistant', content: 'w'},
    {role: 'user', content: 'x'},
    {role: 'assistant', content: 'y'},
    {role: 'user', content: 'z'},
  ],
  model: 'Deepseek-V4-Flash',
  max_tokens: 1024,
  top_p: 0.95,
  min_p: 0.05
}

First Bad Commit

No response

Relevant log output

Logs

0.00.025.641 I cmn  common_param: common_params_print_info: verbosity = 3 (adjust with the `-lv N` CLI arg)
0.00.180.537 I srv    load_model: loading model 'C:\Users\armaguedin\sc\model\DeepSeek-V4-Flash-MXFP4\DeepSeek-V4-Flash-MXFP4-00001-of-00004.gguf'
1.04.891.315 I srv    load_model: initializing, n_slots = 1, n_ctx_slot = 262144, kv_unified = 'false'
1.04.909.094 I srv  llama_server: model loaded
1.04.909.100 I srv  llama_server: listening on http://0.0.0.0:5001
2.55.677.340 I slot get_availabl: id  0 | task -1 | selected slot by LRU, t_last = -1
2.55.677.592 I slot launch_slot_: id  0 | task 0 | processing task, is_child = 0
3.09.176.889 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   2048, progress = 0.08, t =  13.50 s / 151.71 tokens per second
3.16.858.888 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   3510, progress = 0.14, t =  21.18 s / 165.71 tokens per second
3.23.572.700 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4728, progress = 0.18, t =  27.89 s / 169.49 tokens per second
3.26.360.142 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4834, progress = 0.19, t =  30.68 s / 157.55 tokens per second
3.28.578.371 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4881, progress = 0.19, t =  32.90 s / 148.36 tokens per second
3.31.576.882 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4995, progress = 0.19, t =  35.90 s / 139.14 tokens per second
3.34.207.327 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5095, progress = 0.20, t =  38.53 s / 132.24 tokens per second
3.37.224.225 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5222, progress = 0.20, t =  41.55 s / 125.69 tokens per second
3.40.238.546 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5349, progress = 0.21, t =  44.56 s / 120.04 tokens per second
3.43.608.007 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5520, progress = 0.21, t =  47.93 s / 115.17 tokens per second
3.46.937.598 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5680, progress = 0.22, t =  51.26 s / 110.81 tokens per second
3.50.323.104 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5855, progress = 0.23, t =  54.65 s / 107.15 tokens per second
3.52.947.776 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5929, progress = 0.23, t =  57.27 s / 103.53 tokens per second
3.55.387.539 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6005, progress = 0.23, t =  59.71 s / 100.57 tokens per second
3.58.449.497 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6131, progress = 0.24, t =  62.77 s / 97.67 tokens per second
4.01.352.133 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6244, progress = 0.24, t =  65.67 s / 95.08 tokens per second
4.04.332.028 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6379, progress = 0.25, t =  68.65 s / 92.91 tokens per second
4.07.670.559 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6524, progress = 0.25, t =  71.99 s / 90.62 tokens per second
4.10.970.451 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6678, progress = 0.26, t =  75.29 s / 88.69 tokens per second
4.14.255.300 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6833, progress = 0.27, t =  78.58 s / 86.96 tokens per second
4.17.392.394 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6966, progress = 0.27, t =  81.71 s / 85.25 tokens per second
4.20.317.163 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7074, progress = 0.28, t =  84.64 s / 83.58 tokens per second
4.23.161.149 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7167, progress = 0.28, t =  87.48 s / 81.92 tokens per second
4.26.154.679 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7280, progress = 0.28, t =  90.48 s / 80.46 tokens per second
4.29.276.581 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7417, progress = 0.29, t =  93.60 s / 79.24 tokens per second
4.32.329.067 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7538, progress = 0.29, t =  96.65 s / 77.99 tokens per second
4.35.233.572 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7648, progress = 0.30, t =  99.56 s / 76.82 tokens per second
4.38.284.011 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7772, progress = 0.30, t = 102.61 s / 75.75 tokens per second
4.41.329.343 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7884, progress = 0.31, t = 105.65 s / 74.62 tokens per second
4.44.473.010 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8001, progress = 0.31, t = 108.80 s / 73.54 tokens per second
4.47.611.894 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8129, progress = 0.32, t = 111.93 s / 72.62 tokens per second
4.50.971.075 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8297, progress = 0.32, t = 115.29 s / 71.96 tokens per second
4.53.968.000 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8419, progress = 0.33, t = 118.29 s / 71.17 tokens per second
4.57.370.770 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8570, progress = 0.33, t = 121.69 s / 70.42 tokens per second
5.00.284.787 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8678, progress = 0.34, t = 124.61 s / 69.64 tokens per second
5.03.460.485 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8824, progress = 0.34, t = 127.78 s / 69.05 tokens per second
5.06.427.650 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8942, progress = 0.35, t = 130.75 s / 68.39 tokens per second
5.09.618.619 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9078, progress = 0.35, t = 133.94 s / 67.78 tokens per second
5.12.871.733 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9220, progress = 0.36, t = 137.19 s / 67.20 tokens per second
5.16.020.799 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9339, progress = 0.36, t = 140.34 s / 66.54 tokens per second
5.19.211.176 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9486, progress = 0.37, t = 143.53 s / 66.09 tokens per second
5.22.388.851 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9626, progress = 0.37, t = 146.71 s / 65.61 tokens per second
5.25.196.202 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9733, progress = 0.38, t = 149.52 s / 65.10 tokens per second
5.27.824.872 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9829, progress = 0.38, t = 152.15 s / 64.60 tokens per second
5.31.086.457 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9981, progress = 0.39, t = 155.41 s / 64.22 tokens per second
5.33.933.866 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10101, progress = 0.39, t = 158.26 s / 63.83 tokens per second
5.37.010.626 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10216, progress = 0.40, t = 161.33 s / 63.32 tokens per second
5.40.160.732 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10341, progress = 0.40, t = 164.48 s / 62.87 tokens per second
5.43.152.604 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10462, progress = 0.41, t = 167.47 s / 62.47 tokens per second
5.46.420.068 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10604, progress = 0.41, t = 170.74 s / 62.11 tokens per second
5.49.625.843 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10745, progress = 0.42, t = 173.95 s / 61.77 tokens per second
5.52.849.466 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10897, progress = 0.42, t = 177.17 s / 61.51 tokens per second
5.55.958.582 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11025, progress = 0.43, t = 180.28 s / 61.15 tokens per second
5.59.212.637 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11161, progress = 0.43, t = 183.53 s / 60.81 tokens per second
6.01.987.366 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11264, progress = 0.44, t = 186.31 s / 60.46 tokens per second
6.05.151.400 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11402, progress = 0.44, t = 189.47 s / 60.18 tokens per second
6.08.128.498 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11533, progress = 0.45, t = 192.45 s / 59.93 tokens per second
6.11.059.543 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11622, progress = 0.45, t = 195.38 s / 59.48 tokens per second
6.14.306.875 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11758, progress = 0.46, t = 198.63 s / 59.20 tokens per second
6.17.630.785 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11902, progress = 0.46, t = 201.95 s / 58.93 tokens per second
6.20.878.988 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12038, progress = 0.47, t = 205.20 s / 58.66 tokens per second
6.23.906.880 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12157, progress = 0.47, t = 208.23 s / 58.38 tokens per second
6.26.878.425 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12273, progress = 0.48, t = 211.20 s / 58.11 tokens per second
6.30.016.081 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12398, progress = 0.48, t = 214.34 s / 57.84 tokens per second
6.33.182.691 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12515, progress = 0.49, t = 217.50 s / 57.54 tokens per second
6.36.923.633 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12719, progress = 0.49, t = 221.25 s / 57.49 tokens per second
6.40.148.014 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12864, progress = 0.50, t = 224.47 s / 57.31 tokens per second
6.43.291.776 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13006, progress = 0.51, t = 227.61 s / 57.14 tokens per second
6.46.574.221 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13160, progress = 0.51, t = 230.90 s / 57.00 tokens per second
6.49.699.276 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13298, progress = 0.52, t = 234.02 s / 56.82 tokens per second
6.53.105.469 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13444, progress = 0.52, t = 237.43 s / 56.62 tokens per second
6.56.154.123 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13562, progress = 0.53, t = 240.48 s / 56.40 tokens per second
6.59.220.147 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13713, progress = 0.53, t = 243.54 s / 56.31 tokens per second
7.02.727.365 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13885, progress = 0.54, t = 247.05 s / 56.20 tokens per second
7.05.893.302 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14022, progress = 0.55, t = 250.22 s / 56.04 tokens per second
7.08.737.079 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14138, progress = 0.55, t = 253.06 s / 55.87 tokens per second
7.11.956.139 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14279, progress = 0.56, t = 256.28 s / 55.72 tokens per second
7.15.085.419 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14416, progress = 0.56, t = 259.41 s / 55.57 tokens per second
7.18.871.693 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14624, progress = 0.57, t = 263.19 s / 55.56 tokens per second
7.22.157.089 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14783, progress = 0.58, t = 266.48 s / 55.48 tokens per second
7.25.535.402 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14940, progress = 0.58, t = 269.86 s / 55.36 tokens per second
7.28.791.228 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  15085, progress = 0.59, t = 273.11 s / 55.23 tokens per second
7.32.433.847 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  15292, progress = 0.59, t = 276.76 s / 55.25 tokens per second
7.35.822.817 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  15450, progress = 0.60, t = 280.15 s / 55.15 tokens per second
7.39.155.364 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  15591, progress = 0.61, t = 283.48 s / 55.00 tokens per second
7.42.288.031 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  15714, progress = 0.61, t = 286.61 s / 54.83 tokens per second
7.45.804.510 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  15879, progress = 0.62, t = 290.13 s / 54.73 tokens per second
7.49.343.155 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16077, progress = 0.63, t = 293.67 s / 54.75 tokens per second
7.52.884.376 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16236, progress = 0.63, t = 297.21 s / 54.63 tokens per second
7.55.816.510 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16373, progress = 0.64, t = 300.14 s / 54.55 tokens per second
7.59.261.460 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16524, progress = 0.64, t = 303.58 s / 54.43 tokens per second
8.02.755.441 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16691, progress = 0.65, t = 307.08 s / 54.35 tokens per second
8.05.465.080 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16778, progress = 0.65, t = 309.79 s / 54.16 tokens per second
8.08.808.148 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16930, progress = 0.66, t = 313.13 s / 54.07 tokens per second
8.12.532.298 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17133, progress = 0.67, t = 316.85 s / 54.07 tokens per second
8.16.258.771 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17305, progress = 0.67, t = 320.58 s / 53.98 tokens per second
8.20.203.535 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17515, progress = 0.68, t = 324.53 s / 53.97 tokens per second
8.23.550.569 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17653, progress = 0.69, t = 327.87 s / 53.84 tokens per second
8.26.772.556 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17800, progress = 0.69, t = 331.09 s / 53.76 tokens per second
8.30.235.991 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17960, progress = 0.70, t = 334.56 s / 53.68 tokens per second
8.33.761.668 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18133, progress = 0.71, t = 338.08 s / 53.63 tokens per second
8.37.218.534 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18292, progress = 0.71, t = 341.54 s / 53.56 tokens per second
8.40.948.119 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18488, progress = 0.72, t = 345.27 s / 53.55 tokens per second
8.44.124.936 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18631, progress = 0.72, t = 348.45 s / 53.47 tokens per second
8.47.552.835 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18803, progress = 0.73, t = 351.88 s / 53.44 tokens per second
8.51.222.705 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18986, progress = 0.74, t = 355.54 s / 53.40 tokens per second
8.55.197.326 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  19228, progress = 0.75, t = 359.52 s / 53.48 tokens per second
8.59.217.158 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  19472, progress = 0.76, t = 363.54 s / 53.56 tokens per second
9.03.086.896 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  19694, progress = 0.77, t = 367.41 s / 53.60 tokens per second
9.05.933.761 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  19793, progress = 0.77, t = 370.26 s / 53.46 tokens per second
9.09.473.534 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  19966, progress = 0.78, t = 373.80 s / 53.41 tokens per second
9.12.851.872 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  20122, progress = 0.78, t = 377.17 s / 53.35 tokens per second
9.16.549.434 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  20317, progress = 0.79, t = 380.87 s / 53.34 tokens per second
9.20.197.036 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  20513, progress = 0.80, t = 384.52 s / 53.35 tokens per second
9.23.156.891 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  20633, progress = 0.80, t = 387.48 s / 53.25 tokens per second
9.26.338.447 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  20769, progress = 0.81, t = 390.66 s / 53.16 tokens per second
9.29.703.963 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  20921, progress = 0.81, t = 394.03 s / 53.10 tokens per second
9.33.354.745 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  21119, progress = 0.82, t = 397.68 s / 53.11 tokens per second
9.36.866.792 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  21309, progress = 0.83, t = 401.19 s / 53.11 tokens per second
9.40.321.369 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  21489, progress = 0.84, t = 404.64 s / 53.11 tokens per second
9.43.809.991 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  21670, progress = 0.84, t = 408.13 s / 53.10 tokens per second
9.47.050.695 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  21811, progress = 0.85, t = 411.37 s / 53.02 tokens per second
9.50.296.342 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  21963, progress = 0.85, t = 414.62 s / 52.97 tokens per second
9.53.674.339 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  22142, progress = 0.86, t = 418.00 s / 52.97 tokens per second
9.56.835.472 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  22279, progress = 0.87, t = 421.16 s / 52.90 tokens per second
10.00.789.388 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  22476, progress = 0.87, t = 425.11 s / 52.87 tokens per second
10.04.261.477 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  22628, progress = 0.88, t = 428.58 s / 52.80 tokens per second
10.07.457.663 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  22770, progress = 0.89, t = 431.78 s / 52.74 tokens per second
10.10.879.307 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  22923, progress = 0.89, t = 435.20 s / 52.67 tokens per second
10.14.235.517 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23063, progress = 0.90, t = 438.56 s / 52.59 tokens per second
10.17.549.524 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23209, progress = 0.90, t = 441.87 s / 52.52 tokens per second
10.20.540.264 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23323, progress = 0.91, t = 444.86 s / 52.43 tokens per second
10.24.011.688 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23472, progress = 0.91, t = 448.33 s / 52.35 tokens per second
10.27.453.537 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23657, progress = 0.92, t = 451.78 s / 52.36 tokens per second
10.27.764.916 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23658, progress = 0.92, t = 452.09 s / 52.33 tokens per second
10.31.263.244 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23822, progress = 0.93, t = 455.59 s / 52.29 tokens per second
10.34.430.001 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  23962, progress = 0.93, t = 458.75 s / 52.23 tokens per second
10.37.434.255 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24081, progress = 0.94, t = 461.76 s / 52.15 tokens per second
10.40.659.090 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24230, progress = 0.94, t = 464.98 s / 52.11 tokens per second
10.43.564.830 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24354, progress = 0.95, t = 467.89 s / 52.05 tokens per second
10.46.975.400 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24502, progress = 0.95, t = 471.30 s / 51.99 tokens per second
10.50.297.991 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24656, progress = 0.96, t = 474.62 s / 51.95 tokens per second
10.53.349.281 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24798, progress = 0.96, t = 477.67 s / 51.91 tokens per second
10.56.236.444 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  24908, progress = 0.97, t = 480.56 s / 51.83 tokens per second
10.59.172.229 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  25011, progress = 0.97, t = 483.49 s / 51.73 tokens per second
11.05.281.169 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  25702, progress = 1.00, t = 489.60 s / 52.50 tokens per second
11.14.454.552 I slot print_timing: id  0 | task 0 | n_decoded =    100, tg =  11.44 t/s, tg_3s =  11.44 t/s
11.17.459.428 I slot print_timing: id  0 | task 0 | n_decoded =    136, tg =  11.58 t/s, tg_3s =  11.98 t/s
11.20.531.206 I slot print_timing: id  0 | task 0 | n_decoded =    171, tg =  11.54 t/s, tg_3s =  11.39 t/s
11.23.613.555 I slot print_timing: id  0 | task 0 | n_decoded =    208, tg =  11.62 t/s, tg_3s =  12.00 t/s
11.26.617.507 I slot print_timing: id  0 | task 0 | n_decoded =    244, tg =  11.67 t/s, tg_3s =  11.98 t/s
11.29.704.062 I slot print_timing: id  0 | task 0 | n_decoded =    279, tg =  11.63 t/s, tg_3s =  11.34 t/s
11.32.705.229 I slot print_timing: id  0 | task 0 | n_decoded =    315, tg =  11.67 t/s, tg_3s =  12.00 t/s
11.35.788.231 I slot print_timing: id  0 | task 0 | n_decoded =    352, tg =  11.70 t/s, tg_3s =  12.00 t/s
11.38.789.666 I slot print_timing: id  0 | task 0 | n_decoded =    388, tg =  11.73 t/s, tg_3s =  11.99 t/s
11.41.824.833 I slot print_timing: id  0 | task 0 | n_decoded =    423, tg =  11.71 t/s, tg_3s =  11.53 t/s
11.44.835.221 I slot print_timing: id  0 | task 0 | n_decoded =    459, tg =  11.73 t/s, tg_3s =  11.96 t/s
11.47.901.984 I slot print_timing: id  0 | task 0 | n_decoded =    495, tg =  11.73 t/s, tg_3s =  11.74 t/s
11.50.958.085 I slot print_timing: id  0 | task 0 | n_decoded =    531, tg =  11.74 t/s, tg_3s =  11.78 t/s
11.54.016.319 I slot print_timing: id  0 | task 0 | n_decoded =    567, tg =  11.74 t/s, tg_3s =  11.77 t/s
11.57.092.815 I slot print_timing: id  0 | task 0 | n_decoded =    603, tg =  11.74 t/s, tg_3s =  11.70 t/s
12.00.145.709 I slot print_timing: id  0 | task 0 | n_decoded =    639, tg =  11.74 t/s, tg_3s =  11.79 t/s
12.01.664.207 I slot print_timing: id  0 | task 0 | prompt eval time =  490033.41 ms / 25706 tokens (   19.06 ms per token,    52.46 tokens per second)
12.01.664.212 I slot print_timing: id  0 | task 0 |        eval time =   55952.40 ms /   657 tokens (   85.16 ms per token,    11.74 tokens per second)
12.01.664.213 I slot print_timing: id  0 | task 0 |       total time =  545985.81 ms / 26363 tokens
12.01.664.214 I slot print_timing: id  0 | task 0 |    graphs reused =        647
12.01.680.421 I slot      release: id  0 | task 0 | stop processing: n_tokens = 26362, truncated = 0

[ddh0]

I am seeing the same issue, the batch size set and allocated with -b 4096 -ub 4096 does not speed up prompt processing, the prompt is processed in smaller chunks. I am also using DSv4 Flash MXFP4.

[ddh0]

My full launch command is as follows (exportv just sets env vars):

clear
exportv LLAMA_ARG_ALIAS "DeepSeek-V4-Flash"
exportv LLAMA_ARG_MODEL ~/gguf/DeepSeek-V4-Flash-MXFP4-00001-of-00004.gguf
exportv LLAMA_ARG_MMAP 1
exportv LLAMA_ARG_BATCH 4096
exportv LLAMA_ARG_UBATCH 4096
exportv LLAMA_ARG_CTX_SIZE 262144
exportv LLAMA_ARG_N_GPU_LAYERS 999
exportv LLAMA_ARG_OVERRIDE_TENSOR "exps=CPU"
exportv CMD "/home/llama.cpp/build/bin/llama-server -cms $LLAMA_ARG_BATCH -fit 0 -fa 1 $SELF_SPEC --samplers top-k;top-n-sigma;temp --top-k 64 --top-n-sigma 0.9 --temp 1.35"
time $CMD

And here's what happens:

0.53.746.955 I slot   operator(): id  0 | task 0 | new prompt, n_ctx_slot = 262144, n_keep = 0, task.n_tokens = 12876
0.53.746.965 I slot   operator(): id  0 | task 0 | cached n_tokens = 0, memory_seq_rm [0, end)
0.53.747.548 I srv  stream_sessi: conv_id=7dcadd29-481d-4890-8c97-5ba48b90885e (empty=0)
1.55.318.782 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   1458, progress = 0.11, t =  61.57 s / 23.68 tokens per second
1.55.318.785 I slot   operator(): id  0 | task 0 | cached n_tokens = 1458, memory_seq_rm [1458, end)
1.55.333.560 I slot create_check: id  0 | task 0 | created context checkpoint 1 of 64 (pos_min = 1457, pos_max = 1457, n_tokens = 1458, size = 17.021 MiB)
2.28.141.804 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   1964, progress = 0.15, t =  94.39 s / 20.81 tokens per second
2.28.141.807 I slot   operator(): id  0 | task 0 | cached n_tokens = 1964, memory_seq_rm [1964, end)
3.20.233.077 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   2609, progress = 0.20, t = 146.49 s / 17.81 tokens per second
3.20.233.079 I slot   operator(): id  0 | task 0 | cached n_tokens = 2609, memory_seq_rm [2609, end)
3.34.751.062 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   3222, progress = 0.25, t = 161.00 s / 20.01 tokens per second
3.34.751.065 I slot   operator(): id  0 | task 0 | cached n_tokens = 3222, memory_seq_rm [3222, end)
3.48.184.858 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   3806, progress = 0.30, t = 174.44 s / 21.82 tokens per second
3.48.184.862 I slot   operator(): id  0 | task 0 | cached n_tokens = 3806, memory_seq_rm [3806, end)
4.00.920.554 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4486, progress = 0.35, t = 187.17 s / 23.97 tokens per second
4.00.920.557 I slot   operator(): id  0 | task 0 | cached n_tokens = 4486, memory_seq_rm [4486, end)
4.13.047.689 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4902, progress = 0.38, t = 199.30 s / 24.60 tokens per second
4.13.047.691 I slot   operator(): id  0 | task 0 | cached n_tokens = 4902, memory_seq_rm [4902, end)
4.25.574.882 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5325, progress = 0.41, t = 211.83 s / 25.14 tokens per second
4.25.574.884 I slot   operator(): id  0 | task 0 | cached n_tokens = 5325, memory_seq_rm [5325, end)
4.36.316.874 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5767, progress = 0.45, t = 222.57 s / 25.91 tokens per second
4.36.316.877 I slot   operator(): id  0 | task 0 | cached n_tokens = 5767, memory_seq_rm [5767, end)
4.36.326.194 I slot create_check: id  0 | task 0 | created context checkpoint 2 of 64 (pos_min = 5766, pos_max = 5766, n_tokens = 5767, size = 17.021 MiB)
4.46.137.389 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6125, progress = 0.48, t = 232.39 s / 26.36 tokens per second
4.46.137.391 I slot   operator(): id  0 | task 0 | cached n_tokens = 6125, memory_seq_rm [6125, end)
4.55.734.480 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6439, progress = 0.50, t = 241.99 s / 26.61 tokens per second
4.55.734.482 I slot   operator(): id  0 | task 0 | cached n_tokens = 6439, memory_seq_rm [6439, end)
5.05.633.125 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6757, progress = 0.52, t = 251.89 s / 26.83 tokens per second
5.05.633.127 I slot   operator(): id  0 | task 0 | cached n_tokens = 6757, memory_seq_rm [6757, end)
5.16.120.003 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7074, progress = 0.55, t = 262.37 s / 26.96 tokens per second
5.16.120.005 I slot   operator(): id  0 | task 0 | cached n_tokens = 7074, memory_seq_rm [7074, end)
5.30.048.735 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7588, progress = 0.59, t = 276.30 s / 27.46 tokens per second
5.30.048.738 I slot   operator(): id  0 | task 0 | cached n_tokens = 7588, memory_seq_rm [7588, end)
5.43.855.832 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8116, progress = 0.63, t = 290.11 s / 27.98 tokens per second
5.43.855.835 I slot   operator(): id  0 | task 0 | cached n_tokens = 8116, memory_seq_rm [8116, end)
5.55.535.920 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8567, progress = 0.67, t = 301.79 s / 28.39 tokens per second
5.55.535.923 I slot   operator(): id  0 | task 0 | cached n_tokens = 8567, memory_seq_rm [8567, end)
6.03.740.807 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8780, progress = 0.68, t = 309.99 s / 28.32 tokens per second
6.03.740.810 I slot   operator(): id  0 | task 0 | cached n_tokens = 8780, memory_seq_rm [8780, end)
6.07.620.903 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8875, progress = 0.69, t = 313.87 s / 28.28 tokens per second
6.07.620.908 I slot   operator(): id  0 | task 0 | cached n_tokens = 8875, memory_seq_rm [8875, end)
6.19.117.432 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9332, progress = 0.72, t = 325.37 s / 28.68 tokens per second
6.19.117.435 I slot   operator(): id  0 | task 0 | cached n_tokens = 9332, memory_seq_rm [9332, end)
6.33.250.670 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9938, progress = 0.77, t = 339.50 s / 29.27 tokens per second
6.33.250.673 I slot   operator(): id  0 | task 0 | cached n_tokens = 9938, memory_seq_rm [9938, end)
6.33.261.494 I slot create_check: id  0 | task 0 | created context checkpoint 3 of 64 (pos_min = 9937, pos_max = 9937, n_tokens = 9938, size = 17.021 MiB)
6.46.840.104 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10387, progress = 0.81, t = 353.09 s / 29.42 tokens per second
6.46.840.107 I slot   operator(): id  0 | task 0 | cached n_tokens = 10387, memory_seq_rm [10387, end)
6.59.798.707 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10855, progress = 0.84, t = 366.05 s / 29.65 tokens per second
6.59.798.710 I slot   operator(): id  0 | task 0 | cached n_tokens = 10855, memory_seq_rm [10855, end)
7.09.334.435 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11185, progress = 0.87, t = 375.59 s / 29.78 tokens per second
7.09.334.439 I slot   operator(): id  0 | task 0 | cached n_tokens = 11185, memory_seq_rm [11185, end)
7.20.736.665 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11625, progress = 0.90, t = 386.99 s / 30.04 tokens per second
7.20.736.668 I slot   operator(): id  0 | task 0 | cached n_tokens = 11625, memory_seq_rm [11625, end)
7.31.941.572 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12032, progress = 0.93, t = 398.19 s / 30.22 tokens per second
7.31.941.574 I slot   operator(): id  0 | task 0 | cached n_tokens = 12032, memory_seq_rm [12032, end)
7.49.206.635 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12730, progress = 0.99, t = 415.46 s / 30.64 tokens per second
7.49.206.637 I slot   operator(): id  0 | task 0 | cached n_tokens = 12730, memory_seq_rm [12730, end)
7.49.220.161 I slot create_check: id  0 | task 0 | created context checkpoint 4 of 64 (pos_min = 12729, pos_max = 12729, n_tokens = 12730, size = 17.021 MiB)
7.56.155.917 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12872, progress = 1.00, t = 422.41 s / 30.47 tokens per second
7.56.155.921 I slot   operator(): id  0 | task 0 | cached n_tokens = 12872, memory_seq_rm [12872, end)
7.56.166.523 I slot init_sampler: id  0 | task 0 | init sampler, took 5.24 ms, tokens: text = 12876, total = 12876

As you can see it never processes 4096 tokens at once, so prefill speed is never above ~30tk/s in my case. (I'm also offloading partially to disk, so this hurts even more.)

[NovNovikov]

I believe it is the same issue 25213 and the culprit is this commit 24176 which splits the processed batch on every user message start to create a checkpoint

[EugeoSynthesisThirtyTwo]

It's better but it's still not quite there. Some batches are still very small, about 100 tokens.

version: 9941 (683f0c72e)
built with MSVC 19.51.36248.0 for Windows AMD64

llama-server.exe -m Huihui-DeepSeek-V4-Flash-BF16-abliterated-ds4-Q4_K.gguf -a Deepseek-V4-Flash --port 5001 -c 32768 --host 0.0.0.0 -fa on --threads 16 -np 1 --n-gpu-layers 99 --swa-checkpoints 32 --checkpoint-min-step 2048 --no-mmap -ub 2048 -b 2048 -ot "\.*\.ffn_(gate|up|down)_exps.=CPU" -lv 4

1.11.502.665 I srv  llama_server: listening on http://0.0.0.0:5001
1.11.503.009 I srv  update_slots: all slots are idle
1.13.095.437 I srv   operator (): chat format: peg-native
1.13.096.084 I slot get_availabl: id  0 | task -1 | selected slot by LRU, t_last = -1
1.13.096.089 I srv  get_availabl: updating prompt cache
1.13.096.099 I srv          load:  - looking for better prompt, base f_keep = -1.000, sim = 0.000
1.13.096.219 I srv        update:  - cache state: 0 prompts, 0.000 MiB (limits: 8192.000 MiB, 32768 tokens, 8589934592 est)
1.13.096.221 I srv  get_availabl: prompt cache update took 0.13 ms
1.13.096.373 I slot launch_slot_: id  0 | task -1 | sampler chain: logits -> ?penalties -> ?dry -> ?top-n-sigma -> top-k -> ?typical -> ?top-p -> min-p -> ?xtc -> ?temp-ext -> dist
1.13.096.384 I slot launch_slot_: id  0 | task -1 | sampler params:
        repeat_last_n = 64, repeat_penalty = 1.000, frequency_penalty = 0.000, presence_penalty = 0.000
        dry_multiplier = 0.000, dry_base = 1.750, dry_allowed_length = 2, dry_penalty_last_n = 32768
        top_k = 40, top_p = 1.000, min_p = 0.050, xtc_probability = 0.000, xtc_threshold = 0.100, typical_p = 1.000, top_n_sigma = -1.000, temp = 1.000
        mirostat = 0, mirostat_lr = 0.100, mirostat_ent = 5.000, adaptive_target = -1.000, adaptive_decay = 0.900
1.13.096.386 I slot launch_slot_: id  0 | task 0 | processing task, is_child = 0
1.13.096.483 I slot  operator (): id  0 | task 0 | new prompt, n_ctx_slot = 32768, n_keep = 0, task.n_tokens = 18328
1.13.096.499 I slot  operator (): id  0 | task 0 | cached n_tokens = 0, memory_seq_rm [0, end)
1.13.096.743 I srv  stream_sessi: conv_id= (empty=1)
1.29.152.086 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   2048, progress = 0.11, t =  16.06 s / 127.56 tokens per second
1.29.152.093 I slot  operator (): id  0 | task 0 | cached n_tokens = 2048, memory_seq_rm [2048, end)
1.29.431.034 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   2050, progress = 0.11, t =  16.33 s / 125.50 tokens per second
1.29.431.039 I slot  operator (): id  0 | task 0 | cached n_tokens = 2050, memory_seq_rm [2050, end)
1.29.437.678 I slot create_check: id  0 | task 0 | created context checkpoint 1 of 32 (pos_min = 2049, pos_max = 2049, n_tokens = 2050, size = 17.021 MiB)
1.33.980.668 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   2258, progress = 0.12, t =  20.88 s / 108.12 tokens per second
1.33.980.675 I slot  operator (): id  0 | task 0 | cached n_tokens = 2258, memory_seq_rm [2258, end)
1.43.933.956 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4189, progress = 0.23, t =  30.84 s / 135.84 tokens per second
1.43.933.963 I slot  operator (): id  0 | task 0 | cached n_tokens = 4189, memory_seq_rm [4189, end)
1.43.940.119 I slot create_check: id  0 | task 0 | created context checkpoint 2 of 32 (pos_min = 4188, pos_max = 4188, n_tokens = 4189, size = 17.021 MiB)
1.48.036.479 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4334, progress = 0.24, t =  34.94 s / 124.04 tokens per second
1.48.036.485 I slot  operator (): id  0 | task 0 | cached n_tokens = 4334, memory_seq_rm [4334, end)
1.57.787.242 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6332, progress = 0.35, t =  44.69 s / 141.68 tokens per second
1.57.787.248 I slot  operator (): id  0 | task 0 | cached n_tokens = 6332, memory_seq_rm [6332, end)
1.57.794.318 I slot create_check: id  0 | task 0 | created context checkpoint 3 of 32 (pos_min = 6331, pos_max = 6331, n_tokens = 6332, size = 17.021 MiB)
2.02.376.519 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6534, progress = 0.36, t =  49.28 s / 132.59 tokens per second
2.02.376.524 I slot  operator (): id  0 | task 0 | cached n_tokens = 6534, memory_seq_rm [6534, end)
2.11.915.995 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8447, progress = 0.46, t =  58.82 s / 143.61 tokens per second
2.11.916.002 I slot  operator (): id  0 | task 0 | cached n_tokens = 8447, memory_seq_rm [8447, end)
2.11.922.251 I slot create_check: id  0 | task 0 | created context checkpoint 4 of 32 (pos_min = 8446, pos_max = 8446, n_tokens = 8447, size = 17.021 MiB)
2.15.566.480 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   8553, progress = 0.47, t =  62.47 s / 136.91 tokens per second
2.15.566.485 I slot  operator (): id  0 | task 0 | cached n_tokens = 8553, memory_seq_rm [8553, end)
2.24.982.677 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10513, progress = 0.57, t =  71.89 s / 146.25 tokens per second
2.24.982.683 I slot  operator (): id  0 | task 0 | cached n_tokens = 10513, memory_seq_rm [10513, end)
2.24.989.498 I slot create_check: id  0 | task 0 | created context checkpoint 5 of 32 (pos_min = 10512, pos_max = 10512, n_tokens = 10513, size = 17.021 MiB)
2.28.516.289 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  10618, progress = 0.58, t =  75.42 s / 140.79 tokens per second
2.28.516.294 I slot  operator (): id  0 | task 0 | cached n_tokens = 10618, memory_seq_rm [10618, end)
2.38.328.898 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12621, progress = 0.69, t =  85.23 s / 148.08 tokens per second
2.38.328.905 I slot  operator (): id  0 | task 0 | cached n_tokens = 12621, memory_seq_rm [12621, end)
2.38.335.654 I slot create_check: id  0 | task 0 | created context checkpoint 6 of 32 (pos_min = 12620, pos_max = 12620, n_tokens = 12621, size = 17.021 MiB)
2.41.987.353 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  12723, progress = 0.69, t =  88.89 s / 143.13 tokens per second
2.41.987.359 I slot  operator (): id  0 | task 0 | cached n_tokens = 12723, memory_seq_rm [12723, end)
2.52.167.951 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14754, progress = 0.80, t =  99.07 s / 148.92 tokens per second
2.52.167.958 I slot  operator (): id  0 | task 0 | cached n_tokens = 14754, memory_seq_rm [14754, end)
2.52.174.798 I slot create_check: id  0 | task 0 | created context checkpoint 7 of 32 (pos_min = 14753, pos_max = 14753, n_tokens = 14754, size = 17.021 MiB)
2.55.357.609 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  14826, progress = 0.81, t = 102.26 s / 144.98 tokens per second
2.55.357.615 I slot  operator (): id  0 | task 0 | cached n_tokens = 14826, memory_seq_rm [14826, end)
3.04.491.519 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  16280, progress = 0.89, t = 111.40 s / 146.15 tokens per second
3.04.491.525 I slot  operator (): id  0 | task 0 | cached n_tokens = 16280, memory_seq_rm [16280, end)
3.11.756.446 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17013, progress = 0.93, t = 118.66 s / 143.38 tokens per second
3.11.756.452 I slot  operator (): id  0 | task 0 | cached n_tokens = 17013, memory_seq_rm [17013, end)
3.11.763.725 I slot create_check: id  0 | task 0 | created context checkpoint 8 of 32 (pos_min = 17012, pos_max = 17012, n_tokens = 17013, size = 17.021 MiB)
3.16.286.763 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  17163, progress = 0.94, t = 123.19 s / 139.32 tokens per second
3.16.286.768 I slot  operator (): id  0 | task 0 | cached n_tokens = 17163, memory_seq_rm [17163, end)
3.24.975.366 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18304, progress = 1.00, t = 131.88 s / 138.79 tokens per second
3.24.975.373 I slot  operator (): id  0 | task 0 | cached n_tokens = 18304, memory_seq_rm [18304, end)
3.24.982.080 I slot create_check: id  0 | task 0 | created context checkpoint 9 of 32 (pos_min = 18303, pos_max = 18303, n_tokens = 18304, size = 17.021 MiB)
3.25.626.597 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  18324, progress = 1.00, t = 132.53 s / 138.26 tokens per second
3.25.626.603 I slot  operator (): id  0 | task 0 | cached n_tokens = 18324, memory_seq_rm [18324, end)
3.25.628.325 I slot init_sampler: id  0 | task 0 | init sampler, took 1.70 ms, tokens: text = 18328, total = 18328
3.35.353.365 I slot print_timing: id  0 | task 0 | n_decoded =    100, tg =  10.67 t/s, tg_3s =  10.67 t/s
3.38.390.631 I slot print_timing: id  0 | task 0 | n_decoded =    127, tg =  10.23 t/s, tg_3s =   8.89 t/s
3.41.432.450 I slot print_timing: id  0 | task 0 | n_decoded =    160, tg =  10.36 t/s, tg_3s =  10.85 t/s
3.44.484.391 I slot print_timing: id  0 | task 0 | n_decoded =    193, tg =  10.43 t/s, tg_3s =  10.81 t/s
3.47.527.198 I slot print_timing: id  0 | task 0 | n_decoded =    226, tg =  10.49 t/s, tg_3s =  10.85 t/s
3.50.551.800 I slot print_timing: id  0 | task 0 | n_decoded =    257, tg =  10.46 t/s, tg_3s =  10.25 t/s
3.51.389.066 I slot print_timing: id  0 | task 0 | prompt eval time =  132884.15 ms / 18328 tokens (    7.25 ms per token,   137.92 tokens per second)
3.51.389.072 I slot print_timing: id  0 | task 0 |        eval time =   25407.31 ms /   266 tokens (   95.52 ms per token,    10.47 tokens per second)
3.51.389.073 I slot print_timing: id  0 | task 0 |       total time =  158291.46 ms / 18594 tokens
3.51.389.074 I slot print_timing: id  0 | task 0 |    graphs reused =        260
3.51.404.517 I slot      release: id  0 | task 0 | stop processing: n_tokens = 18593, truncated = 0
3.51.404.537 I srv  update_slots: all slots are idle

[EugeoSynthesisThirtyTwo]

How can I reopen the issue ?

[aldehir]

Double your --checkpoint-min-step.

[NovNovikov]

Shouldn't it work fine on default settings? Or, basically, on most settings?

[aldehir]

The default settings will maintain a good distance between user message checkpoints that you will see less processing of batches with size < n_batch.

It is improbable that user messages fall cleanly along n_batch boundaries, so you will occasionally see processing of smaller batches. This is exacerbated in contrived examples, where messages are kept short to demonstrate the issue.

You can tune --checkpoint-min-step to reduce such occurrences (or disable checkpointing, which is probably less desirable).

[EugeoSynthesisThirtyTwo]

I mean, I have min-step=2048, ubatch=2048, and batch=2048, so why are these messages not concatenated ?

4.46.137.389 I slot print_timing: id 0 | task 0 | prompt processing, n_tokens = 6125, progress = 0.48, t = 232.39 s / 26.36 tokens per second
4.46.137.391 I slot operator(): id 0 | task 0 | cached n_tokens = 6125, memory_seq_rm [6125, end)
4.55.734.480 I slot print_timing: id 0 | task 0 | prompt processing, n_tokens = 6439, progress = 0.50, t = 241.99 s / 26.61 tokens per second
4.55.734.482 I slot operator(): id 0 | task 0 | cached n_tokens = 6439, memory_seq_rm [6439, end)
5.05.633.125 I slot print_timing: id 0 | task 0 | prompt processing, n_tokens = 6757, progress = 0.52, t = 251.89 s / 26.83 tokens per second
5.05.633.127 I slot operator(): id 0 | task 0 | cached n_tokens = 6757, memory_seq_rm [6757, end)
5.16.120.003 I slot print_timing: id 0 | task 0 | prompt processing, n_tokens = 7074, progress = 0.55, t = 262.37 s / 26.96 tokens per second
5.16.120.005 I slot operator(): id 0 | task 0 | cached n_tokens = 7074, memory_seq_rm [7074, end)
5.30.048.735 I slot print_timing: id 0 | task 0 | prompt processing, n_tokens = 7588, progress = 0.59, t = 276.30 s / 27.46 tokens per second
5.30.048.738 I slot operator(): id 0 | task 0 | cached n_tokens = 7588, memory_seq_rm [7588, end)
5.43.855.832 I slot print_timing: id 0 | task 0 | prompt processing, n_tokens = 8116, progress = 0.63, t = 290.11 s / 27.98 tokens per second
5.43.855.835 I slot operator(): id 0 | task 0 | cached n_tokens = 8116, memory_seq_rm [8116, end)

[ddh0]

Unfortunately I can confirm that I am also still seeing this issue on the latest master. It seems to be better sometimes, in that batches are sometimes more full than before, but it is still splitting into user-message-sized batches which kills PP. DSv4 flash. Let me know if I can provide more information.

[aldehir]

Unfortunately I can confirm that I am also still seeing this issue on the latest master. It seems to be better sometimes, in that batches are sometimes more full than before, but it is still splitting into user-message-sized batches which kills PP. DSv4 flash. Let me know if I can provide more information.

What arguments are you passing in?

[ddh0]

What arguments are you passing in?

Here is my full launch command:

export LLAMA_ARG_REASONING=1
export LLAMA_ARG_THINK_BUDGET=4096
export LLAMA_ARG_ALIAS="DeepSeek-V4-Flash"
export LLAMA_ARG_CHAT_TEMPLATE_FILE="~/jinja/dsv4.jinja"
export LLAMA_ARG_MODEL="~/gguf/DeepSeek-V4-Flash-MXFP4-00001-of-00002.gguf"
export LLAMA_ARG_MMAP=1
export LLAMA_ARG_BATCH=4096
export LLAMA_ARG_UBATCH=4096
export LLAMA_ARG_CTX_SIZE=131072

/home/llama.cpp/build/bin/llama-server --ui-mcp-proxy --jinja -cms 4096 --spec-type none -fit 1 -fitt 1024 -fa 1 --samplers "top-k;top-n-sigma;temp" --top-k 64 --top-n-sigma 0.85 --temp 1.15

And this is an example of the behaviour I am seeing (long chat messages, some batches are full):

1.10.887.420 I slot   operator(): id  0 | task 0 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 11679
1.10.887.620 I slot   operator(): id  0 | task 0 | cached n_tokens = 0, memory_seq_rm [0, end)
1.10.887.923 I srv  server_strea: conv_id=1d5ac976-72bd-4ff0-8207-eac9dd766a55 (empty=0)
2.12.187.210 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   4096, progress = 0.35, t =  61.30 s / 66.82 tokens per second
2.12.187.213 I slot   operator(): id  0 | task 0 | cached n_tokens = 4096, memory_seq_rm [4096, end)
3.44.364.761 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5430, progress = 0.46, t = 153.48 s / 35.38 tokens per second
3.44.364.767 I slot   operator(): id  0 | task 0 | cached n_tokens = 5430, memory_seq_rm [5430, end)
3.44.545.361 I slot create_check: id  0 | task 0 | created context checkpoint 1 of 64 (pos_min = 5429, pos_max = 5429, n_tokens = 5430, size = 17.021 MiB)
4.18.679.880 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   5603, progress = 0.48, t = 187.79 s / 29.84 tokens per second
4.18.679.884 I slot   operator(): id  0 | task 0 | cached n_tokens = 5603, memory_seq_rm [5603, end)
4.18.687.506 I slot create_check: id  0 | task 0 | created context checkpoint 2 of 64 (pos_min = 5602, pos_max = 5602, n_tokens = 5603, size = 17.021 MiB)
5.02.644.694 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   7583, progress = 0.65, t = 231.76 s / 32.72 tokens per second
5.02.644.696 I slot   operator(): id  0 | task 0 | cached n_tokens = 7583, memory_seq_rm [7583, end)
6.03.024.739 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11675, progress = 1.00, t = 292.14 s / 39.96 tokens per second
6.03.024.742 I slot   operator(): id  0 | task 0 | cached n_tokens = 11675, memory_seq_rm [11675, end)
6.03.034.835 I slot init_sampler: id  0 | task 0 | init sampler, took 4.89 ms, tokens: text = 11679, total = 11679
6.03.082.454 I slot create_check: id  0 | task 0 | created context checkpoint 3 of 64 (pos_min = 11674, pos_max = 11674, n_tokens = 11675, size = 17.021 MiB)

And another example with mostly small chat messages, it looks like only one of these batches is completely filled:

8.30.462.208 I slot   operator(): id  0 | task 205 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 14186
8.30.462.214 I slot   operator(): id  0 | task 205 | cached n_tokens = 0, memory_seq_rm [0, end)
8.30.462.679 I srv  server_strea: conv_id=55d53410-2d4b-4bf3-8934-78eeacc0c45f (empty=0)
9.30.331.974 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =   3305, progress = 0.23, t =  59.87 s / 55.20 tokens per second
9.30.332.311 I slot   operator(): id  0 | task 205 | cached n_tokens = 3305, memory_seq_rm [3305, end)
9.30.421.608 I slot create_check: id  0 | task 205 | created context checkpoint 1 of 64 (pos_min = 3304, pos_max = 3304, n_tokens = 3305, size = 17.021 MiB)
10.35.154.185 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =   7401, progress = 0.52, t = 124.69 s / 59.35 tokens per second
10.35.154.368 I slot   operator(): id  0 | task 205 | cached n_tokens = 7401, memory_seq_rm [7401, end)
11.09.970.560 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =   7614, progress = 0.54, t = 159.51 s / 47.73 tokens per second
11.09.970.564 I slot   operator(): id  0 | task 205 | cached n_tokens = 7614, memory_seq_rm [7614, end)
11.09.979.406 I slot create_check: id  0 | task 205 | created context checkpoint 2 of 64 (pos_min = 7613, pos_max = 7613, n_tokens = 7614, size = 17.021 MiB)
11.44.449.050 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =  10090, progress = 0.71, t = 193.99 s / 52.01 tokens per second
11.44.449.052 I slot   operator(): id  0 | task 205 | cached n_tokens = 10090, memory_seq_rm [10090, end)
12.05.139.701 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =  11785, progress = 0.83, t = 214.68 s / 54.90 tokens per second
12.05.139.703 I slot   operator(): id  0 | task 205 | cached n_tokens = 11785, memory_seq_rm [11785, end)
12.05.166.064 I slot create_check: id  0 | task 205 | created context checkpoint 3 of 64 (pos_min = 11784, pos_max = 11784, n_tokens = 11785, size = 17.021 MiB)
12.35.723.338 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =  13944, progress = 0.98, t = 245.26 s / 56.85 tokens per second
12.35.723.341 I slot   operator(): id  0 | task 205 | cached n_tokens = 13944, memory_seq_rm [13944, end)
12.35.756.729 I slot create_check: id  0 | task 205 | created context checkpoint 4 of 64 (pos_min = 13943, pos_max = 13943, n_tokens = 13944, size = 17.021 MiB)
12.48.328.341 I slot print_timing: id  0 | task 205 | prompt processing, n_tokens =  14182, progress = 1.00, t = 257.87 s / 55.00 tokens per second
12.48.328.344 I slot   operator(): id  0 | task 205 | cached n_tokens = 14182, memory_seq_rm [14182, end)
12.48.331.900 I slot init_sampler: id  0 | task 205 | init sampler, took 1.55 ms, tokens: text = 14186, total = 14186

I would expect that the -cms argument, which I have set to 4096 here, would prevent these smaller processing batches. And it does seem to limit the frequency of checkpoints enough.

However, even when processing is not broken up by checkpoints, the batches are often still smaller than they need to be, which sacrifices processing speed. Granted, my ceiling for performance is not so high in the first place, and I'm just trying to squeeze out all the performance that I can.

This behaviour seems odd. I will also load up a non-deepseek model and report back here soon.

[ddh0]

Same chat processing with gemma 4 31B (no MTP, no mtmd). Using -b == -ub == -cms == 4096.

0.28.871.926 I slot launch_slot_: id  0 | task 0 | processing task, is_child = 0
0.28.871.936 I slot   operator(): id  0 | task 0 | new prompt, n_ctx_slot = 65536, n_keep = 0, task.n_tokens = 13722
0.28.871.945 I slot   operator(): id  0 | task 0 | cached n_tokens = 0, memory_seq_rm [0, end)
0.28.872.024 I srv  server_strea: conv_id=55d53410-2d4b-4bf3-8934-78eeacc0c45f (empty=0)
0.33.465.091 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   2649, progress = 0.19, t =   4.59 s / 576.73 tokens per second
0.33.465.093 I slot   operator(): id  0 | task 0 | cached n_tokens = 2649, memory_seq_rm [2649, end)
0.33.768.244 I slot create_check: id  0 | task 0 | created context checkpoint 1 of 64 (pos_min = 0, pos_max = 2648, n_tokens = 2649, size = 800.013 MiB)
0.41.704.686 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6745, progress = 0.49, t =  12.83 s / 525.61 tokens per second
0.41.704.688 I slot   operator(): id  0 | task 0 | cached n_tokens = 6745, memory_seq_rm [6745, end)
0.49.013.553 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   6973, progress = 0.51, t =  20.14 s / 346.20 tokens per second
0.49.013.556 I slot   operator(): id  0 | task 0 | cached n_tokens = 6973, memory_seq_rm [6973, end)
0.49.314.571 I slot create_check: id  0 | task 0 | created context checkpoint 2 of 64 (pos_min = 1853, pos_max = 6972, n_tokens = 6973, size = 800.013 MiB)
0.54.769.530 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =   9626, progress = 0.70, t =  25.90 s / 371.69 tokens per second
0.54.769.533 I slot   operator(): id  0 | task 0 | cached n_tokens = 9626, memory_seq_rm [9626, end)
0.58.570.557 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  11242, progress = 0.82, t =  29.70 s / 378.54 tokens per second
0.58.570.559 I slot   operator(): id  0 | task 0 | cached n_tokens = 11242, memory_seq_rm [11242, end)
0.58.890.927 I slot create_check: id  0 | task 0 | created context checkpoint 3 of 64 (pos_min = 6122, pos_max = 11241, n_tokens = 11242, size = 800.013 MiB)
1.03.744.449 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13465, progress = 0.98, t =  34.87 s / 386.12 tokens per second
1.03.744.451 I slot   operator(): id  0 | task 0 | cached n_tokens = 13465, memory_seq_rm [13465, end)
1.04.074.274 I slot create_check: id  0 | task 0 | created context checkpoint 4 of 64 (pos_min = 8345, pos_max = 13464, n_tokens = 13465, size = 800.013 MiB)
1.12.793.438 I slot print_timing: id  0 | task 0 | prompt processing, n_tokens =  13718, progress = 1.00, t =  43.92 s / 312.33 tokens per second
1.12.793.441 I slot   operator(): id  0 | task 0 | cached n_tokens = 13718, memory_seq_rm [13718, end)
1.12.794.482 I slot init_sampler: id  0 | task 0 | init sampler, took 1.00 ms, tokens: text = 13722, total = 13722

Looks like only 1 full batch.