Skip to content

Eval bug: Gemma 4 tool call returned as content #22786

@leidegre

Description

@leidegre

Name and Version

.\llama-cli.exe --version
ggml_cuda_init: found 1 CUDA devices (Total VRAM: 12281 MiB):
Device 0: NVIDIA GeForce RTX 4070, compute capability 8.9, VMM: yes, VRAM: 12281 MiB
load_backend: loaded CUDA backend from E:\llama.cpp\ggml-cuda.dll
load_backend: loaded RPC backend from E:\llama.cpp\ggml-rpc.dll
load_backend: loaded CPU backend from E:\llama.cpp\ggml-cpu-haswell.dll
version: 8919 (dc80c52)
built with Clang 19.1.5 for Windows x86_64

Operating systems

Windows

GGML backends

CUDA

Hardware

Ryzen 5950X + RTX 4070

Models

ggml-org/gemma-4-E4B-it-GGUF:Q8_0
ggml-org/gemma-4-E4B-it-GGUF:BF16

Problem description & steps to reproduce

Tool call is rendered as content instead of being parsed as a tool call. This is a correct tool call but it's not picked up as a tool call. What's funny is that just before this, I make a different /v1/chat/completions call (and it works correctly) to get into this sub agent which is managing memory with a different system prompt, albeit much smaller one.

<|tool_call>call:CommitMemoryTool{memory: "The user's name is John."}<tool_call|>

This has worked fine before but now It's reproducing consistently... and I'm not sure why. I tried different quants but it didn't make a difference. I'll gladly dig around a bit to figure this out but am a bit at loss on what to do next... any advice is very much apricated.

First Bad Commit

No response

Relevant log output

Logs
ggml_cuda_init: found 1 CUDA devices (Total VRAM: 12281 MiB):
  Device 0: NVIDIA GeForce RTX 4070, compute capability 8.9, VMM: yes, VRAM: 12281 MiB
load_backend: loaded CUDA backend from E:\llama.cpp\ggml-cuda.dll
load_backend: loaded RPC backend from E:\llama.cpp\ggml-rpc.dll
load_backend: loaded CPU backend from E:\llama.cpp\ggml-cpu-haswell.dll
common_download_file_single_online: HEAD failed, status: 404
no remote preset found, skipping
Downloading gemma-4-E4B-it-bf16.gguf ─────────────────────────────── 100%
build_info: b8919-dc80c5252
system_info: n_threads = 16 (n_threads_batch = 16) / 32 | CUDA : ARCHS = 500,610,700,750,800,860,890 | USE_GRAPHS = 1 | PEER_MAX_BATCH_SIZE = 128 | CPU : SSE3 = 1 | SSSE3 = 1 | AVX = 1 | AVX2 = 1 | F16C = 1 | FMA = 1 | BMI2 = 1 | LLAMAFILE = 1 | OPENMP = 1 | REPACK = 1 |
Running without SSL
init: using 31 threads for HTTP server
start: binding port with default address family
main: loading model
srv    load_model: loading model 'E:\llama.cpp_cache\models--ggml-org--gemma-4-E4B-it-GGUF\snapshots\2714b5519c6c3516b1000e7c5e1eba998dfe1fe8\gemma-4-E4B-it-bf16.gguf'
common_init_result: fitting params to device memory, for bugs during this step try to reproduce them with -fit off, or provide --verbose logs if the bug only occurs with -fit on
common_params_fit_impl: getting device memory data for initial parameters:
common_memory_breakdown_print: | memory breakdown [MiB] | total    free     self   model   context   compute       unaccounted |
common_memory_breakdown_print: |   - CUDA0 (RTX 4070)   | 12281 = 11094 + (10876 =  8964 +    1109 +     802) + 17592186034727 |
common_memory_breakdown_print: |   - Host               |                   6946 =  6656 +       0 +     290                   |
common_params_fit_impl: projected to use 10876 MiB of device memory vs. 11094 MiB of free device memory
common_params_fit_impl: cannot meet free memory target of 1024 MiB, need to reduce device memory by 806 MiB
common_params_fit_impl: context size set by user to 131072 -> no change
common_params_fit_impl: id=0, target=10070 MiB
common_memory_breakdown_print: | memory breakdown [MiB] | total    free     self   model   context   compute       unaccounted |
common_memory_breakdown_print: |   - CUDA0 (RTX 4070)   | 12281 = 11094 + ( 1823 =     0 +       0 +    1823) + 17592186043780 |
common_memory_breakdown_print: |   - Host               |                  17020 = 15620 +    1109 +     290                   |
common_params_fit_impl: memory for test allocation by device:
common_params_fit_impl: id=0, n_layer= 0, n_part= 0, overflow_type=4, mem=  1823 MiB
common_params_fit_impl: filling dense layers back-to-front:
common_memory_breakdown_print: | memory breakdown [MiB] | total    free     self   model   context   compute       unaccounted |
common_memory_breakdown_print: |   - CUDA0 (RTX 4070)   | 12281 = 11094 + (10876 =  8964 +    1109 +     802) + 17592186034727 |
common_memory_breakdown_print: |   - Host               |                   6946 =  6656 +       0 +     290                   |
common_params_fit_impl: memory for test allocation by device:
common_params_fit_impl: id=0, n_layer=43, n_part= 0, overflow_type=4, mem= 10876 MiB
common_params_fit_impl: start filling device 0, delta=43
common_memory_breakdown_print: | memory breakdown [MiB] | total    free    self   model   context   compute       unaccounted |
common_memory_breakdown_print: |   - CUDA0 (RTX 4070)   | 12281 = 11094 + (9844 =  8201 +    1105 +     538) + 17592186035758 |
common_memory_breakdown_print: |   - Host               |                  7713 =  7418 +       4 +     290                   |
common_params_fit_impl: memory for test allocation by device:
common_params_fit_impl: id=0, n_layer=39, n_part= 0, overflow_type=4, mem=  9844 MiB
common_params_fit_impl: set ngl_per_device[0].n_layer=39
common_memory_breakdown_print: | memory breakdown [MiB] | total    free     self   model   context   compute       unaccounted |
common_memory_breakdown_print: |   - CUDA0 (RTX 4070)   | 12281 = 11094 + (10023 =  8379 +    1106 +     538) + 17592186035579 |
common_memory_breakdown_print: |   - Host               |                   7534 =  7241 +       3 +     290                   |
common_params_fit_impl: memory for test allocation by device:
common_params_fit_impl: id=0, n_layer=40, n_part= 0, overflow_type=4, mem= 10023 MiB
common_params_fit_impl: set ngl_per_device[0].n_layer=40
common_memory_breakdown_print: | memory breakdown [MiB] | total    free     self   model   context   compute       unaccounted |
common_memory_breakdown_print: |   - CUDA0 (RTX 4070)   | 12281 = 11094 + (10202 =  8557 +    1107 +     538) + 17592186035401 |
common_memory_breakdown_print: |   - Host               |                   7356 =  7063 +       2 +     290                   |
common_params_fit_impl: memory for test allocation by device:
common_params_fit_impl: id=0, n_layer=41, n_part= 0, overflow_type=4, mem= 10202 MiB
common_params_fit_impl: set ngl_per_device_high[0].n_layer=41
common_params_fit_impl:   - CUDA0 (NVIDIA GeForce RTX 4070): 40 layers,  10023 MiB used,   1070 MiB free
common_fit_params: successfully fit params to free device memory
common_fit_params: fitting params to free memory took 0.60 seconds
llama_model_load_from_file_impl: using device CUDA0 (NVIDIA GeForce RTX 4070) (0000:0a:00.0) - 11094 MiB free
llama_model_loader: loaded meta data with 44 key-value pairs and 720 tensors from E:\llama.cpp_cache\models--ggml-org--gemma-4-E4B-it-GGUF\snapshots\2714b5519c6c3516b1000e7c5e1eba998dfe1fe8\gemma-4-E4B-it-bf16.gguf (version GGUF V3 (latest))
llama_model_loader: Dumping metadata keys/values. Note: KV overrides do not apply in this output.
llama_model_loader: - kv   0:                       general.architecture str              = gemma4
llama_model_loader: - kv   1:                               general.type str              = model
llama_model_loader: - kv   2:                     general.sampling.top_k i32              = 64
llama_model_loader: - kv   3:                     general.sampling.top_p f32              = 0.950000
llama_model_loader: - kv   4:                      general.sampling.temp f32              = 1.000000
llama_model_loader: - kv   5:                         general.size_label str              = 7.5B
llama_model_loader: - kv   6:                            general.license str              = apache-2.0
llama_model_loader: - kv   7:                       general.license.link str              = https://ai.google.dev/gemma/docs/gemm...
llama_model_loader: - kv   8:                               general.tags arr[str,1]       = ["any-to-any"]
llama_model_loader: - kv   9:                         gemma4.block_count u32              = 42
llama_model_loader: - kv  10:                      gemma4.context_length u32              = 131072
llama_model_loader: - kv  11:                    gemma4.embedding_length u32              = 2560
llama_model_loader: - kv  12:                 gemma4.feed_forward_length u32              = 10240
llama_model_loader: - kv  13:                gemma4.attention.head_count u32              = 8
llama_model_loader: - kv  14:             gemma4.attention.head_count_kv u32              = 2
llama_model_loader: - kv  15:                      gemma4.rope.freq_base f32              = 1000000.000000
llama_model_loader: - kv  16:                  gemma4.rope.freq_base_swa f32              = 10000.000000
llama_model_loader: - kv  17:    gemma4.attention.layer_norm_rms_epsilon f32              = 0.000001
llama_model_loader: - kv  18:                gemma4.attention.key_length u32              = 512
llama_model_loader: - kv  19:              gemma4.attention.value_length u32              = 512
llama_model_loader: - kv  20:                          general.file_type u32              = 32
llama_model_loader: - kv  21:             gemma4.final_logit_softcapping f32              = 30.000000
llama_model_loader: - kv  22:            gemma4.attention.sliding_window u32              = 512
llama_model_loader: - kv  23:          gemma4.attention.shared_kv_layers u32              = 18
llama_model_loader: - kv  24:    gemma4.embedding_length_per_layer_input u32              = 256
llama_model_loader: - kv  25:    gemma4.attention.sliding_window_pattern arr[bool,42]     = [true, true, true, true, true, false,...
llama_model_loader: - kv  26:            gemma4.attention.key_length_swa u32              = 256
llama_model_loader: - kv  27:          gemma4.attention.value_length_swa u32              = 256
llama_model_loader: - kv  28:                gemma4.rope.dimension_count u32              = 512
llama_model_loader: - kv  29:            gemma4.rope.dimension_count_swa u32              = 256
llama_model_loader: - kv  30:               general.quantization_version u32              = 2
llama_model_loader: - kv  31:                       tokenizer.ggml.model str              = gemma4
llama_model_loader: - kv  32:                      tokenizer.ggml.tokens arr[str,262144]  = ["<pad>", "<eos>", "<bos>", "<unk>", ...
llama_model_loader: - kv  33:                      tokenizer.ggml.scores arr[f32,262144]  = [-1000.000000, -1000.000000, -1000.00...
llama_model_loader: - kv  34:                  tokenizer.ggml.token_type arr[i32,262144]  = [3, 3, 3, 3, 3, 1, 1, 1, 1, 1, 1, 1, ...
llama_model_loader: - kv  35:                      tokenizer.ggml.merges arr[str,514906]  = ["\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n\n \n", ...
llama_model_loader: - kv  36:                tokenizer.ggml.bos_token_id u32              = 2
llama_model_loader: - kv  37:                tokenizer.ggml.eos_token_id u32              = 1
llama_model_loader: - kv  38:            tokenizer.ggml.unknown_token_id u32              = 3
llama_model_loader: - kv  39:            tokenizer.ggml.padding_token_id u32              = 0
llama_model_loader: - kv  40:               tokenizer.ggml.mask_token_id u32              = 4
llama_model_loader: - kv  41:                    tokenizer.chat_template str              = {%- macro format_parameters(propertie...
llama_model_loader: - kv  42:            tokenizer.ggml.add_space_prefix bool             = false
llama_model_loader: - kv  43:               tokenizer.ggml.add_bos_token bool             = true
llama_model_loader: - type  f32:  339 tensors
llama_model_loader: - type bf16:  381 tensors
print_info: file format = GGUF V3 (latest)
print_info: file type   = BF16
print_info: file size   = 14.00 GiB (16.00 BPW)
load: 0 unused tokens
load: control-looking token:     50 '<|tool_response>' was not control-type; this is probably a bug in the model. its type will be overridden
load: control-looking token:    212 '</s>' was not control-type; this is probably a bug in the model. its type will be overridden
load: printing all EOG tokens:
load:   - 1 ('<eos>')
load:   - 50 ('<|tool_response>')
load:   - 106 ('<turn|>')
load:   - 212 ('</s>')
load: special_eog_ids contains '<|tool_response>', removing '</s>' token from EOG list
load: special tokens cache size = 24
load: token to piece cache size = 1.9445 MB
print_info: arch                  = gemma4
print_info: vocab_only            = 0
print_info: no_alloc              = 0
print_info: n_ctx_train           = 131072
print_info: n_embd                = 2560
print_info: n_embd_inp            = 2560
print_info: n_layer               = 42
print_info: n_head                = 8
print_info: n_head_kv             = 2
print_info: n_rot                 = 512
print_info: n_swa                 = 512
print_info: is_swa_any            = 1
print_info: n_embd_head_k         = 512
print_info: n_embd_head_v         = 512
print_info: n_gqa                 = 4
print_info: n_embd_k_gqa          = [512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024]
print_info: n_embd_v_gqa          = [512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024, 512, 512, 512, 512, 512, 1024]
print_info: f_norm_eps            = 0.0e+00
print_info: f_norm_rms_eps        = 1.0e-06
print_info: f_clamp_kqv           = 0.0e+00
print_info: f_max_alibi_bias      = 0.0e+00
print_info: f_logit_scale         = 0.0e+00
print_info: f_attn_scale          = 1.0e+00
print_info: n_ff                  = 10240
print_info: n_expert              = 0
print_info: n_expert_used         = 0
print_info: n_expert_groups       = 0
print_info: n_group_used          = 0
print_info: causal attn           = 1
print_info: pooling type          = -1
print_info: rope type             = 2
print_info: rope scaling          = linear
print_info: freq_base_train       = 1000000.0
print_info: freq_scale_train      = 1
print_info: freq_base_swa         = 10000.0
print_info: freq_scale_swa        = 1
print_info: n_embd_head_k_swa     = 256
print_info: n_embd_head_v_swa     = 256
print_info: n_rot_swa             = 256
print_info: n_ctx_orig_yarn       = 131072
print_info: rope_yarn_log_mul     = 0.0000
print_info: rope_finetuned        = unknown
print_info: model type            = E4B
print_info: model params          = 7.52 B
print_info: general.name          = n/a
print_info: vocab type            = BPE
print_info: n_vocab               = 262144
print_info: n_merges              = 514906
print_info: BOS token             = 2 '<bos>'
print_info: EOS token             = 1 '<eos>'
print_info: UNK token             = 3 '<unk>'
print_info: PAD token             = 0 '<pad>'
print_info: MASK token            = 4 '<mask>'
print_info: LF token              = 107 '
'
print_info: EOG token             = 1 '<eos>'
print_info: EOG token             = 50 '<|tool_response>'
print_info: EOG token             = 106 '<turn|>'
print_info: max token length      = 93
load_tensors: loading model tensors, this can take a while... (mmap = true, direct_io = false)
load_tensors: offloading output layer to GPU
load_tensors: offloading 39 repeating layers to GPU
load_tensors: offloaded 40/43 layers to GPU
load_tensors:   CPU_Mapped model buffer size = 14340.66 MiB
load_tensors:        CUDA0 model buffer size =  8379.51 MiB
.....................................................
common_init_result: added <eos> logit bias = -inf
common_init_result: added <|tool_response> logit bias = -inf
common_init_result: added <turn|> logit bias = -inf
llama_context: constructing llama_context
llama_context: n_seq_max     = 1
llama_context: n_ctx         = 131072
llama_context: n_ctx_seq     = 131072
llama_context: n_batch       = 2048
llama_context: n_ubatch      = 512
llama_context: causal_attn   = 1
llama_context: flash_attn    = auto
llama_context: kv_unified    = false
llama_context: freq_base     = 1000000.0
llama_context: freq_scale    = 1
llama_context:  CUDA_Host  output buffer size =     1.00 MiB
llama_kv_cache_iswa: creating non-SWA KV cache, size = 131072 cells
llama_kv_cache:      CUDA0 KV buffer size =  1088.00 MiB
llama_kv_cache: size = 1088.00 MiB (131072 cells,   4 layers,  1/1 seqs), K (q8_0):  544.00 MiB, V (q8_0):  544.00 MiB
llama_kv_cache: attn_rot_k = 1, n_embd_head_k_all = 512
llama_kv_cache: attn_rot_v = 1, n_embd_head_k_all = 512
llama_kv_cache_iswa: creating     SWA KV cache, size = 1024 cells
llama_kv_cache:        CPU KV buffer size =     3.19 MiB
llama_kv_cache:      CUDA0 KV buffer size =    18.06 MiB
llama_kv_cache: size =   21.25 MiB (  1024 cells,  20 layers,  1/1 seqs), K (q8_0):   10.62 MiB, V (q8_0):   10.62 MiB
llama_kv_cache: attn_rot_k = 1, n_embd_head_k_all = 256
llama_kv_cache: attn_rot_v = 1, n_embd_head_k_all = 256
sched_reserve: reserving ...
sched_reserve: Flash Attention was auto, set to enabled
sched_reserve: resolving fused Gated Delta Net support:
sched_reserve: fused Gated Delta Net (autoregressive) enabled
sched_reserve: fused Gated Delta Net (chunked) enabled
sched_reserve:      CUDA0 compute buffer size =   538.00 MiB
sched_reserve:  CUDA_Host compute buffer size =   290.30 MiB
sched_reserve: graph nodes  = 2263
sched_reserve: graph splits = 61 (with bs=512), 5 (with bs=1)
sched_reserve: reserve took 29.36 ms, sched copies = 1
common_init_from_params: warming up the model with an empty run - please wait ... (--no-warmup to disable)
clip_model_loader: model name:
clip_model_loader: description:
clip_model_loader: GGUF version: 3
clip_model_loader: alignment:    32
clip_model_loader: n_tensors:    1411
clip_model_loader: n_kv:         32

clip_model_loader: has vision encoder
clip_model_loader: has audio encoder
clip_ctx: CLIP using CUDA0 backend
load_hparams: projector:          gemma4v
load_hparams: n_embd:             768
load_hparams: n_head:             12
load_hparams: n_ff:               3072
load_hparams: n_layer:            16
load_hparams: ffn_op:             gelu_quick
load_hparams: projection_dim:     2560

--- vision hparams ---
load_hparams: image_size:         224
load_hparams: patch_size:         16
load_hparams: has_llava_proj:     0
load_hparams: minicpmv_version:   0
load_hparams: n_merge:            3
load_hparams: n_wa_pattern: 0
load_hparams: image_min_pixels:   580608
load_hparams: image_max_pixels:   645120

load_hparams: model size:         945.51 MiB
load_hparams: metadata size:      0.50 MiB
warmup: warmup with image size = 768 x 768
alloc_compute_meta:      CUDA0 compute buffer size =    94.52 MiB
alloc_compute_meta:        CPU compute buffer size =     6.77 MiB
alloc_compute_meta: graph splits = 1, nodes = 940
warmup: flash attention is enabled
clip_ctx: CLIP using CUDA0 backend
load_hparams: projector:          gemma4a
load_hparams: n_embd:             1024
load_hparams: n_head:             8
load_hparams: n_ff:               4096
load_hparams: n_layer:            12
load_hparams: ffn_op:             gelu_quick
load_hparams: projection_dim:     2560

--- audio hparams ---
load_hparams: n_mel_bins:         128
load_hparams: proj_stack_factor:  0
load_hparams: audio_chunk_len:    0
load_hparams: audio_sample_rate:  16000
load_hparams: audio_n_fft:        512
load_hparams: audio_window_len:   320
load_hparams: audio_hop_len:      160

load_hparams: model size:         945.51 MiB
load_hparams: metadata size:      0.50 MiB
warmup: warmup with audio size = 3000
alloc_compute_meta:      CUDA0 compute buffer size =   153.93 MiB
alloc_compute_meta:        CPU compute buffer size =     1.58 MiB
alloc_compute_meta: graph splits = 1, nodes = 1448
warmup: flash attention is enabled
init_audio: audio input is in experimental stage and may have reduced quality:
    https://github.com/ggml-org/llama.cpp/discussions/13759
srv    load_model: loaded multimodal model, 'E:\llama.cpp_cache\models--ggml-org--gemma-4-E4B-it-GGUF\snapshots\2714b5519c6c3516b1000e7c5e1eba998dfe1fe8\mmproj-gemma-4-E4B-it-bf16.gguf'
srv    load_model: initializing slots, n_slots = 1
no implementations specified for speculative decoding
slot   load_model: id  0 | task -1 | new slot, n_ctx = 131072
srv    load_model: prompt cache is enabled, size limit: 8192 MiB
srv    load_model: use `--cache-ram 0` to disable the prompt cache
srv    load_model: for more info see https://github.com/ggml-org/llama.cpp/pull/16391
srv          init: init: --cache-idle-slots requires --kv-unified, disabling
init: chat template, example_format: '<|turn>system
<|think|>
You are a helpful assistant<turn|>
<|turn>user
Hello<turn|>
<|turn>model
Hi there<turn|>
<|turn>user
How are you?<turn|>
<|turn>model
'
srv          init: init: chat template, thinking = 1
main: model loaded
main: server is listening on http://127.0.0.1:8080
main: starting the main loop...
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LRU, t_last = -1
srv  get_availabl: updating prompt cache
srv          load:  - looking for better prompt, base f_keep = -1.000, sim = 0.000
srv        update:  - cache state: 0 prompts, 0.000 MiB (limits: 8192.000 MiB, 131072 tokens, 8589934592 est)
srv  get_availabl: prompt cache update took 0.01 ms
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
slot launch_slot_: id  0 | task 0 | processing task, is_child = 0
slot update_slots: id  0 | task 0 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 2356
slot update_slots: id  0 | task 0 | n_tokens = 0, memory_seq_rm [0, end)
slot update_slots: id  0 | task 0 | prompt processing progress, n_tokens = 1840, batch.n_tokens = 1840, progress = 0.780985
slot update_slots: id  0 | task 0 | n_tokens = 1840, memory_seq_rm [1840, end)
slot update_slots: id  0 | task 0 | prompt processing progress, n_tokens = 2352, batch.n_tokens = 512, progress = 0.998302
slot create_check: id  0 | task 0 | created context checkpoint 1 of 32 (pos_min = 816, pos_max = 1839, n_tokens = 1840, size = 21.262 MiB)
slot update_slots: id  0 | task 0 | n_tokens = 2352, memory_seq_rm [2352, end)
slot init_sampler: id  0 | task 0 | init sampler, took 0.24 ms, tokens: text = 2356, total = 2356
slot update_slots: id  0 | task 0 | prompt processing done, n_tokens = 2356, batch.n_tokens = 4
slot create_check: id  0 | task 0 | created context checkpoint 2 of 32 (pos_min = 1328, pos_max = 2351, n_tokens = 2352, size = 21.262 MiB)
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
reasoning-budget: activated, budget=2147483647 tokens
reasoning-budget: deactivated (natural end)
slot print_timing: id  0 | task 0 |
prompt eval time =    1298.56 ms /  2356 tokens (    0.55 ms per token,  1814.32 tokens per second)
       eval time =    3700.39 ms /    81 tokens (   45.68 ms per token,    21.89 tokens per second)
      total time =    4998.95 ms /  2437 tokens
slot      release: id  0 | task 0 | stop processing: n_tokens = 2436, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LCP similarity, sim_best = 0.990 (> 0.100 thold), f_keep = 0.967
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
slot launch_slot_: id  0 | task 84 | processing task, is_child = 0
slot update_slots: id  0 | task 84 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 2381
slot update_slots: id  0 | task 84 | n_tokens = 2356, memory_seq_rm [2356, end)
slot update_slots: id  0 | task 84 | prompt processing progress, n_tokens = 2377, batch.n_tokens = 21, progress = 0.998320
slot update_slots: id  0 | task 84 | n_tokens = 2377, memory_seq_rm [2377, end)
slot init_sampler: id  0 | task 84 | init sampler, took 0.26 ms, tokens: text = 2381, total = 2381
slot update_slots: id  0 | task 84 | prompt processing done, n_tokens = 2381, batch.n_tokens = 4
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
reasoning-budget: activated, budget=2147483647 tokens
reasoning-budget: deactivated (natural end)
slot print_timing: id  0 | task 84 |
prompt eval time =     287.55 ms /    25 tokens (   11.50 ms per token,    86.94 tokens per second)
       eval time =    2336.66 ms /    52 tokens (   44.94 ms per token,    22.25 tokens per second)
      total time =    2624.21 ms /    77 tokens
slot      release: id  0 | task 84 | stop processing: n_tokens = 2432, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LRU, t_last = 33427988
srv  get_availabl: updating prompt cache
srv   prompt_save:  - saving prompt with length 2432, total state size = 41.395 MiB
srv          load:  - looking for better prompt, base f_keep = 0.003, sim = 0.024
srv        update:  - cache state: 1 prompts, 83.919 MiB (limits: 8192.000 MiB, 131072 tokens, 237406 est)
srv        update:    - prompt 000002430A5CE8A0:    2432 tokens, checkpoints:  2,    83.919 MiB
srv  get_availabl: prompt cache update took 19.98 ms
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
slot launch_slot_: id  0 | task 138 | processing task, is_child = 0
slot update_slots: id  0 | task 138 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 336
slot update_slots: id  0 | task 138 | n_past = 8, slot.prompt.tokens.size() = 2432, seq_id = 0, pos_min = 1412, n_swa = 512
slot update_slots: id  0 | task 138 | Checking checkpoint with [1328, 2351] against 0...
slot update_slots: id  0 | task 138 | Checking checkpoint with [816, 1839] against 0...
slot update_slots: id  0 | task 138 | forcing full prompt re-processing due to lack of cache data (likely due to SWA or hybrid/recurrent memory, see https://github.com/ggml-org/llama.cpp/pull/13194#issuecomment-2868343055)
slot update_slots: id  0 | task 138 | erased invalidated context checkpoint (pos_min = 816, pos_max = 1839, n_tokens = 1840, n_swa = 512, pos_next = 0, size = 21.262 MiB)
slot update_slots: id  0 | task 138 | erased invalidated context checkpoint (pos_min = 1328, pos_max = 2351, n_tokens = 2352, n_swa = 512, pos_next = 0, size = 21.262 MiB)
slot update_slots: id  0 | task 138 | n_tokens = 0, memory_seq_rm [0, end)
slot update_slots: id  0 | task 138 | prompt processing progress, n_tokens = 332, batch.n_tokens = 332, progress = 0.988095
slot update_slots: id  0 | task 138 | n_tokens = 332, memory_seq_rm [332, end)
slot init_sampler: id  0 | task 138 | init sampler, took 0.04 ms, tokens: text = 336, total = 336
slot update_slots: id  0 | task 138 | prompt processing done, n_tokens = 336, batch.n_tokens = 4
slot create_check: id  0 | task 138 | created context checkpoint 1 of 32 (pos_min = 0, pos_max = 331, n_tokens = 332, size = 6.894 MiB)
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
slot print_timing: id  0 | task 138 |
prompt eval time =     216.53 ms /   336 tokens (    0.64 ms per token,  1551.75 tokens per second)
       eval time =   13637.42 ms /   304 tokens (   44.86 ms per token,    22.29 tokens per second)
      total time =   13853.95 ms /   640 tokens
slot      release: id  0 | task 138 | stop processing: n_tokens = 639, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LCP similarity, sim_best = 0.870 (> 0.100 thold), f_keep = 0.526
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
slot launch_slot_: id  0 | task 444 | processing task, is_child = 0
slot update_slots: id  0 | task 444 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 386
slot update_slots: id  0 | task 444 | n_past = 336, slot.prompt.tokens.size() = 639, seq_id = 0, pos_min = 0, n_swa = 512
slot update_slots: id  0 | task 444 | Checking checkpoint with [0, 331] against 0...
slot update_slots: id  0 | task 444 | restored context checkpoint (pos_min = 0, pos_max = 331, n_tokens = 332, n_past = 331, size = 6.894 MiB)
slot update_slots: id  0 | task 444 | n_tokens = 331, memory_seq_rm [331, end)
slot update_slots: id  0 | task 444 | prompt processing progress, n_tokens = 382, batch.n_tokens = 51, progress = 0.989637
slot update_slots: id  0 | task 444 | n_tokens = 382, memory_seq_rm [382, end)
slot init_sampler: id  0 | task 444 | init sampler, took 0.04 ms, tokens: text = 386, total = 386
slot update_slots: id  0 | task 444 | prompt processing done, n_tokens = 386, batch.n_tokens = 4
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
slot print_timing: id  0 | task 444 |
prompt eval time =     165.55 ms /    55 tokens (    3.01 ms per token,   332.22 tokens per second)
       eval time =   13583.28 ms /   300 tokens (   45.28 ms per token,    22.09 tokens per second)
      total time =   13748.84 ms /   355 tokens
slot      release: id  0 | task 444 | stop processing: n_tokens = 685, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LCP similarity, sim_best = 0.885 (> 0.100 thold), f_keep = 0.564
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
slot launch_slot_: id  0 | task 746 | processing task, is_child = 0
slot update_slots: id  0 | task 746 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 436
slot update_slots: id  0 | task 746 | n_past = 386, slot.prompt.tokens.size() = 685, seq_id = 0, pos_min = 0, n_swa = 512
slot update_slots: id  0 | task 746 | Checking checkpoint with [0, 331] against 0...
slot update_slots: id  0 | task 746 | restored context checkpoint (pos_min = 0, pos_max = 331, n_tokens = 332, n_past = 331, size = 6.894 MiB)
slot update_slots: id  0 | task 746 | n_tokens = 331, memory_seq_rm [331, end)
slot update_slots: id  0 | task 746 | prompt processing progress, n_tokens = 432, batch.n_tokens = 101, progress = 0.990826
slot update_slots: id  0 | task 746 | n_tokens = 432, memory_seq_rm [432, end)
slot init_sampler: id  0 | task 746 | init sampler, took 0.05 ms, tokens: text = 436, total = 436
slot update_slots: id  0 | task 746 | prompt processing done, n_tokens = 436, batch.n_tokens = 4
slot create_check: id  0 | task 746 | created context checkpoint 2 of 32 (pos_min = 0, pos_max = 431, n_tokens = 432, size = 8.970 MiB)
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
slot print_timing: id  0 | task 746 |
prompt eval time =     191.31 ms /   105 tokens (    1.82 ms per token,   548.86 tokens per second)
       eval time =   16905.73 ms /   372 tokens (   45.45 ms per token,    22.00 tokens per second)
      total time =   17097.03 ms /   477 tokens
slot      release: id  0 | task 746 | stop processing: n_tokens = 807, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LCP similarity, sim_best = 0.897 (> 0.100 thold), f_keep = 0.540
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
slot launch_slot_: id  0 | task 1120 | processing task, is_child = 0
slot update_slots: id  0 | task 1120 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 486
slot update_slots: id  0 | task 1120 | n_past = 436, slot.prompt.tokens.size() = 807, seq_id = 0, pos_min = 0, n_swa = 512
slot update_slots: id  0 | task 1120 | Checking checkpoint with [0, 431] against 0...
slot update_slots: id  0 | task 1120 | restored context checkpoint (pos_min = 0, pos_max = 431, n_tokens = 432, n_past = 431, size = 8.970 MiB)
slot update_slots: id  0 | task 1120 | n_tokens = 431, memory_seq_rm [431, end)
slot update_slots: id  0 | task 1120 | prompt processing progress, n_tokens = 482, batch.n_tokens = 51, progress = 0.991770
slot update_slots: id  0 | task 1120 | n_tokens = 482, memory_seq_rm [482, end)
slot init_sampler: id  0 | task 1120 | init sampler, took 0.06 ms, tokens: text = 486, total = 486
slot update_slots: id  0 | task 1120 | prompt processing done, n_tokens = 486, batch.n_tokens = 4
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
slot print_timing: id  0 | task 1120 |
prompt eval time =     162.09 ms /    55 tokens (    2.95 ms per token,   339.31 tokens per second)
       eval time =   13712.33 ms /   303 tokens (   45.26 ms per token,    22.10 tokens per second)
      total time =   13874.43 ms /   358 tokens
slot      release: id  0 | task 1120 | stop processing: n_tokens = 788, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LCP similarity, sim_best = 0.905 (> 0.100 thold), f_keep = 0.617
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
slot launch_slot_: id  0 | task 1425 | processing task, is_child = 0
slot update_slots: id  0 | task 1425 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 537
slot update_slots: id  0 | task 1425 | n_past = 486, slot.prompt.tokens.size() = 788, seq_id = 0, pos_min = 0, n_swa = 512
slot update_slots: id  0 | task 1425 | Checking checkpoint with [0, 431] against 0...
slot update_slots: id  0 | task 1425 | restored context checkpoint (pos_min = 0, pos_max = 431, n_tokens = 432, n_past = 431, size = 8.970 MiB)
slot update_slots: id  0 | task 1425 | n_tokens = 431, memory_seq_rm [431, end)
slot update_slots: id  0 | task 1425 | prompt processing progress, n_tokens = 533, batch.n_tokens = 102, progress = 0.992551
slot update_slots: id  0 | task 1425 | n_tokens = 533, memory_seq_rm [533, end)
slot init_sampler: id  0 | task 1425 | init sampler, took 0.06 ms, tokens: text = 537, total = 537
slot update_slots: id  0 | task 1425 | prompt processing done, n_tokens = 537, batch.n_tokens = 4
slot create_check: id  0 | task 1425 | created context checkpoint 3 of 32 (pos_min = 0, pos_max = 532, n_tokens = 533, size = 11.067 MiB)
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
slot print_timing: id  0 | task 1425 |
prompt eval time =     173.27 ms /   106 tokens (    1.63 ms per token,   611.77 tokens per second)
       eval time =   31496.63 ms /   664 tokens (   47.43 ms per token,    21.08 tokens per second)
      total time =   31669.89 ms /   770 tokens
slot      release: id  0 | task 1425 | stop processing: n_tokens = 1200, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LRU, t_last = 123762374
srv  get_availabl: updating prompt cache
srv   prompt_save:  - saving prompt with length 1200, total state size = 31.237 MiB
srv          load:  - looking for better prompt, base f_keep = 0.007, sim = 0.003
srv          load:  - found better prompt with f_keep = 0.979, sim = 0.984
srv        update:  - cache state: 1 prompts, 58.169 MiB (limits: 8192.000 MiB, 131072 tokens, 168998 est)
srv        update:    - prompt 000002431CEFEF50:    1200 tokens, checkpoints:  3,    58.169 MiB
srv  get_availabl: prompt cache update took 25.72 ms
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
slot launch_slot_: id  0 | task 2091 | processing task, is_child = 0
slot update_slots: id  0 | task 2091 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 2419
slot update_slots: id  0 | task 2091 | n_tokens = 2381, memory_seq_rm [2381, end)
slot update_slots: id  0 | task 2091 | prompt processing progress, n_tokens = 2415, batch.n_tokens = 34, progress = 0.998346
slot update_slots: id  0 | task 2091 | n_tokens = 2415, memory_seq_rm [2415, end)
slot init_sampler: id  0 | task 2091 | init sampler, took 0.25 ms, tokens: text = 2419, total = 2419
slot update_slots: id  0 | task 2091 | prompt processing done, n_tokens = 2419, batch.n_tokens = 4
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
reasoning-budget: activated, budget=2147483647 tokens
reasoning-budget: deactivated (natural end)
slot print_timing: id  0 | task 2091 |
prompt eval time =     167.06 ms /    38 tokens (    4.40 ms per token,   227.47 tokens per second)
       eval time =    7994.18 ms /   171 tokens (   46.75 ms per token,    21.39 tokens per second)
      total time =    8161.24 ms /   209 tokens
slot      release: id  0 | task 2091 | stop processing: n_tokens = 2589, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LCP similarity, sim_best = 0.996 (> 0.100 thold), f_keep = 0.906
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
slot launch_slot_: id  0 | task 2264 | processing task, is_child = 0
slot update_slots: id  0 | task 2264 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 2354
slot update_slots: id  0 | task 2264 | erased invalidated context checkpoint (pos_min = 1328, pos_max = 2351, n_tokens = 2352, n_swa = 512, pos_next = 2345, size = 21.262 MiB)
slot update_slots: id  0 | task 2264 | n_tokens = 2345, memory_seq_rm [2345, end)
slot update_slots: id  0 | task 2264 | prompt processing progress, n_tokens = 2350, batch.n_tokens = 5, progress = 0.998301
slot create_check: id  0 | task 2264 | created context checkpoint 2 of 32 (pos_min = 1569, pos_max = 2344, n_tokens = 2345, size = 16.113 MiB)
slot update_slots: id  0 | task 2264 | n_tokens = 2350, memory_seq_rm [2350, end)
slot init_sampler: id  0 | task 2264 | init sampler, took 0.27 ms, tokens: text = 2354, total = 2354
slot update_slots: id  0 | task 2264 | prompt processing done, n_tokens = 2354, batch.n_tokens = 4
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
reasoning-budget: activated, budget=2147483647 tokens
reasoning-budget: deactivated (natural end)
slot print_timing: id  0 | task 2264 |
prompt eval time =     145.21 ms /     9 tokens (   16.13 ms per token,    61.98 tokens per second)
       eval time =    4393.76 ms /    93 tokens (   47.24 ms per token,    21.17 tokens per second)
      total time =    4538.97 ms /   102 tokens
slot      release: id  0 | task 2264 | stop processing: n_tokens = 2446, truncated = 0
srv  update_slots: all slots are idle
srv  params_from_: Chat format: peg-gemma4
slot get_availabl: id  0 | task -1 | selected slot by LRU, t_last = 186279504
srv  get_availabl: updating prompt cache
srv   prompt_save:  - saving prompt with length 2446, total state size = 38.542 MiB
srv          load:  - looking for better prompt, base f_keep = 0.003, sim = 0.024
srv          load:  - found better prompt with f_keep = 0.280, sim = 1.000
srv        update:  - cache state: 1 prompts, 75.917 MiB (limits: 8192.000 MiB, 131072 tokens, 263941 est)
srv        update:    - prompt 000002431AB793D0:    2446 tokens, checkpoints:  2,    75.917 MiB
srv  get_availabl: prompt cache update took 26.06 ms
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
slot launch_slot_: id  0 | task 2359 | processing task, is_child = 0
slot update_slots: id  0 | task 2359 | new prompt, n_ctx_slot = 131072, n_keep = 0, task.n_tokens = 336
slot update_slots: id  0 | task 2359 | n_past = 336, slot.prompt.tokens.size() = 1200, seq_id = 0, pos_min = 176, n_swa = 512
slot update_slots: id  0 | task 2359 | Checking checkpoint with [0, 532] against 0...
slot update_slots: id  0 | task 2359 | restored context checkpoint (pos_min = 0, pos_max = 532, n_tokens = 533, n_past = 336, size = 11.067 MiB)
slot update_slots: id  0 | task 2359 | erased invalidated context checkpoint (pos_min = 0, pos_max = 431, n_tokens = 432, n_swa = 512, pos_next = 336, size = 8.970 MiB)
slot update_slots: id  0 | task 2359 | erased invalidated context checkpoint (pos_min = 0, pos_max = 532, n_tokens = 533, n_swa = 512, pos_next = 336, size = 11.067 MiB)
slot update_slots: id  0 | task 2359 | need to evaluate at least 1 token for each active slot (n_past = 336, task.n_tokens() = 336)
slot update_slots: id  0 | task 2359 | n_past was set to 335
slot update_slots: id  0 | task 2359 | n_tokens = 335, memory_seq_rm [335, end)
slot init_sampler: id  0 | task 2359 | init sampler, took 0.04 ms, tokens: text = 336, total = 336
slot update_slots: id  0 | task 2359 | prompt processing done, n_tokens = 336, batch.n_tokens = 1
srv  log_server_r: done request: POST /v1/chat/completions 127.0.0.1 200
slot print_timing: id  0 | task 2359 |
prompt eval time =      54.04 ms /     1 tokens (   54.04 ms per token,    18.51 tokens per second)
       eval time =   14780.88 ms /   310 tokens (   47.68 ms per token,    20.97 tokens per second)
      total time =   14834.92 ms /   311 tokens
slot      release: id  0 | task 2359 | stop processing: n_tokens = 645, truncated = 0
srv  update_slots: all slots are idle

Metadata

Metadata

Assignees

No one assigned

    Type

    No type
    No fields configured for issues without a type.

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions