Bug: llama-server api first query very slow

[bosmart]

What happened?

I'm using the openai library to interact with llama-server docker image on an A6000:

docker run -p 8080:8080 --name llama-server -v ~/gguf_models:/models --gpus all ghcr.io/ggerganov/llama.cpp:server-cuda -m models/Meta-Llama-3.1-70B-Instruct-Q4_K_L.gguf -c 65536 -fa --host 0.0.0.0 --port 8080 --n-gpu-layers 99 -ctk q4_0 -ctv q4_0 -t 4

The first request I send takes about 80 seconds, during which at first a single CPU core gets 100% load for maybe ~55s (with GPU usage at 0%) and only then the GPU kicks in. The second time I execute the exact same call, it takes ~26s to respond and starts with both CPU (one core 100%) and GPU (~87%) working a the same time.

The API call itself is:

import openai  # openai-1.45.0

api_url = 'http://x.x.x.x:8080'

client = openai.OpenAI(
    base_url=f"{api_url}/v1",
    api_key = "unused"
)

messages = [
    {"role": "system", "content": "You are a helpful assistant. Your top priority is answering user questions truthfully, based solely on the information provided."},
    {"role": "user", "content": prompt} # prompt is around 450 words
]

completion = client.chat.completions.create(
    model=None,
    temperature=0.0,
    messages=messages
).choices[0].message

Name and Version

$./llama-server --version
version: 0 (unknown)
built with cc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 for x86_64-linux-gnu

^^^ not very helpful but I have just pulled a fresh docker image today i.e. 15/09/2024:
docker pull ghcr.io/ggerganov/llama.cpp:server-cuda

What operating system are you seeing the problem on?

Linux

Relevant log output

warn: LLAMA_ARG_HOST environment variable is set, but will be overwritten by command line argument --host
INFO [                    main] build info | tid="126087453233152" timestamp=1726381552 build=0 commit="unknown"
INFO [                    main] system info | tid="126087453233152" timestamp=1726381552 n_threads=4 n_threads_batch=4 total_threads=36 system_info="AVX = 1 | AVX_VNNI = 0 | AVX2 = 1 | AVX512 = 0 | AVX512_VBMI = 0 | AVX512_VNNI = 0 | AVX512_BF16 = 0 | FMA = 1 | NEON = 0 | SVE = 0 | ARM_FMA = 0 | F16C = 1 | FP16_VA = 0 | RISCV_VECT = 0 | WASM_SIMD = 0 | BLAS = 1 | SSE3 = 1 | SSSE3 = 1 | VSX = 0 | MATMUL_INT8 = 0 | LLAMAFILE = 1 | "
INFO [                    main] HTTP server is listening | tid="126087453233152" timestamp=1726381552 n_threads_http="35" port="8080" hostname="0.0.0.0"
INFO [                    main] loading model | tid="126087453233152" timestamp=1726381552 n_threads_http="35" port="8080" hostname="0.0.0.0"
llama_model_loader: loaded meta data with 33 key-value pairs and 724 tensors from models/Meta-Llama-3.1-70B-Instruct-Q4_K_L.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              = llama
llama_model_loader: - kv   1:                               general.type str              = model
llama_model_loader: - kv   2:                               general.name str              = Meta Llama 3.1 70B Instruct
llama_model_loader: - kv   3:                           general.finetune str              = Instruct
llama_model_loader: - kv   4:                           general.basename str              = Meta-Llama-3.1
llama_model_loader: - kv   5:                         general.size_label str              = 70B
llama_model_loader: - kv   6:                            general.license str              = llama3.1
llama_model_loader: - kv   7:                               general.tags arr[str,6]       = ["facebook", "meta", "pytorch", "llam...
llama_model_loader: - kv   8:                          general.languages arr[str,8]       = ["en", "de", "fr", "it", "pt", "hi", ...
llama_model_loader: - kv   9:                          llama.block_count u32              = 80
llama_model_loader: - kv  10:                       llama.context_length u32              = 131072
llama_model_loader: - kv  11:                     llama.embedding_length u32              = 8192
llama_model_loader: - kv  12:                  llama.feed_forward_length u32              = 28672
llama_model_loader: - kv  13:                 llama.attention.head_count u32              = 64
llama_model_loader: - kv  14:              llama.attention.head_count_kv u32              = 8
llama_model_loader: - kv  15:                       llama.rope.freq_base f32              = 500000.000000
llama_model_loader: - kv  16:     llama.attention.layer_norm_rms_epsilon f32              = 0.000010
llama_model_loader: - kv  17:                          general.file_type u32              = 15
llama_model_loader: - kv  18:                           llama.vocab_size u32              = 128256
llama_model_loader: - kv  19:                 llama.rope.dimension_count u32              = 128
llama_model_loader: - kv  20:                       tokenizer.ggml.model str              = gpt2
llama_model_loader: - kv  21:                         tokenizer.ggml.pre str              = llama-bpe
llama_model_loader: - kv  22:                      tokenizer.ggml.tokens arr[str,128256]  = ["!", "\"", "#", "$", "%", "&", "'", ...
llama_model_loader: - kv  23:                  tokenizer.ggml.token_type arr[i32,128256]  = [1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, ...
llama_model_loader: - kv  24:                      tokenizer.ggml.merges arr[str,280147]  = ["Ġ Ġ", "Ġ ĠĠĠ", "ĠĠ ĠĠ", "...
llama_model_loader: - kv  25:                tokenizer.ggml.bos_token_id u32              = 128000
llama_model_loader: - kv  26:                tokenizer.ggml.eos_token_id u32              = 128009
llama_model_loader: - kv  27:                    tokenizer.chat_template str              = {{- bos_token }}\n{%- if custom_tools ...
llama_model_loader: - kv  28:               general.quantization_version u32              = 2
llama_model_loader: - kv  29:                      quantize.imatrix.file str              = /models_out/Meta-Llama-3.1-70B-Instru...
llama_model_loader: - kv  30:                   quantize.imatrix.dataset str              = /training_dir/calibration_datav3.txt
llama_model_loader: - kv  31:             quantize.imatrix.entries_count i32              = 560
llama_model_loader: - kv  32:              quantize.imatrix.chunks_count i32              = 125
llama_model_loader: - type  f32:  162 tensors
llama_model_loader: - type q8_0:    2 tensors
llama_model_loader: - type q4_K:  440 tensors
llama_model_loader: - type q5_K:   40 tensors
llama_model_loader: - type q6_K:   80 tensors
llm_load_vocab: special tokens cache size = 256
llm_load_vocab: token to piece cache size = 0.7999 MB
llm_load_print_meta: format           = GGUF V3 (latest)
llm_load_print_meta: arch             = llama
llm_load_print_meta: vocab type       = BPE
llm_load_print_meta: n_vocab          = 128256
llm_load_print_meta: n_merges         = 280147
llm_load_print_meta: vocab_only       = 0
llm_load_print_meta: n_ctx_train      = 131072
llm_load_print_meta: n_embd           = 8192
llm_load_print_meta: n_layer          = 80
llm_load_print_meta: n_head           = 64
llm_load_print_meta: n_head_kv        = 8
llm_load_print_meta: n_rot            = 128
llm_load_print_meta: n_swa            = 0
llm_load_print_meta: n_embd_head_k    = 128
llm_load_print_meta: n_embd_head_v    = 128
llm_load_print_meta: n_gqa            = 8
llm_load_print_meta: n_embd_k_gqa     = 1024
llm_load_print_meta: n_embd_v_gqa     = 1024
llm_load_print_meta: f_norm_eps       = 0.0e+00
llm_load_print_meta: f_norm_rms_eps   = 1.0e-05
llm_load_print_meta: f_clamp_kqv      = 0.0e+00
llm_load_print_meta: f_max_alibi_bias = 0.0e+00
llm_load_print_meta: f_logit_scale    = 0.0e+00
llm_load_print_meta: n_ff             = 28672
llm_load_print_meta: n_expert         = 0
llm_load_print_meta: n_expert_used    = 0
llm_load_print_meta: causal attn      = 1
llm_load_print_meta: pooling type     = 0
llm_load_print_meta: rope type        = 0
llm_load_print_meta: rope scaling     = linear
llm_load_print_meta: freq_base_train  = 500000.0
llm_load_print_meta: freq_scale_train = 1
llm_load_print_meta: n_ctx_orig_yarn  = 131072
llm_load_print_meta: rope_finetuned   = unknown
llm_load_print_meta: ssm_d_conv       = 0
llm_load_print_meta: ssm_d_inner      = 0
llm_load_print_meta: ssm_d_state      = 0
llm_load_print_meta: ssm_dt_rank      = 0
llm_load_print_meta: ssm_dt_b_c_rms   = 0
llm_load_print_meta: model type       = 70B
llm_load_print_meta: model ftype      = Q4_K - Medium
llm_load_print_meta: model params     = 70.55 B
llm_load_print_meta: model size       = 40.32 GiB (4.91 BPW)
llm_load_print_meta: general.name     = Meta Llama 3.1 70B Instruct
llm_load_print_meta: BOS token        = 128000 '<|begin_of_text|>'
llm_load_print_meta: EOS token        = 128009 '<|eot_id|>'
llm_load_print_meta: LF token         = 128 'Ä'
llm_load_print_meta: EOT token        = 128009 '<|eot_id|>'
llm_load_print_meta: max token length = 256
ggml_cuda_init: GGML_CUDA_FORCE_MMQ:    no
ggml_cuda_init: GGML_CUDA_FORCE_CUBLAS: no
ggml_cuda_init: found 1 CUDA devices:
  Device 0: NVIDIA RTX A6000, compute capability 8.6, VMM: yes
llm_load_tensors: ggml ctx size =    0.68 MiB
llm_load_tensors: offloading 80 repeating layers to GPU
llm_load_tensors: offloading non-repeating layers to GPU
llm_load_tensors: offloaded 81/81 layers to GPU
llm_load_tensors:        CPU buffer size =  1064.62 MiB
llm_load_tensors:      CUDA0 buffer size = 40222.18 MiB
.................................................................................................
llama_new_context_with_model: n_ctx      = 65536
llama_new_context_with_model: n_batch    = 2048
llama_new_context_with_model: n_ubatch   = 512
llama_new_context_with_model: flash_attn = 1
llama_new_context_with_model: freq_base  = 500000.0
llama_new_context_with_model: freq_scale = 1
llama_kv_cache_init:      CUDA0 KV buffer size =  5760.00 MiB
llama_new_context_with_model: KV self size  = 5760.00 MiB, K (q4_0): 2880.00 MiB, V (q4_0): 2880.00 MiB
llama_new_context_with_model:  CUDA_Host  output buffer size =     0.98 MiB
llama_new_context_with_model:      CUDA0 compute buffer size =   266.50 MiB
llama_new_context_with_model:  CUDA_Host compute buffer size =   144.01 MiB
llama_new_context_with_model: graph nodes  = 2247
llama_new_context_with_model: graph splits = 2
INFO [                    init] initializing slots | tid="126087453233152" timestamp=1726381574 n_slots=1
INFO [                    init] new slot | tid="126087453233152" timestamp=1726381574 id_slot=0 n_ctx_slot=65536
INFO [                    main] model loaded | tid="126087453233152" timestamp=1726381574
INFO [                    main] chat template | tid="126087453233152" timestamp=1726381574 chat_example="<|start_header_id|>system<|end_header_id|>\n\nYou are a helpful assistant<|eot_id|><|start_header_id|>user<|end_header_id|>\n\nHello<|eot_id|><|start_header_id|>assistant<|end_header_id|>\n\nHi there<|eot_id|><|start_header_id|>user<|end_header_id|>\n\nHow are you?<|eot_id|><|start_header_id|>assistant<|end_header_id|>\n\n" built_in=true
INFO [            update_slots] all slots are idle | tid="126087453233152" timestamp=1726381574
INFO [      log_server_request] request | tid="126086914506752" timestamp=1726381582 remote_addr="127.0.0.1" remote_port=35744 status=200 method="GET" path="/health" params={}
INFO [   launch_slot_with_task] slot is processing task | tid="126087453233152" timestamp=1726381587 id_slot=0 id_task=0
INFO [            update_slots] kv cache rm [p0, end) | tid="126087453233152" timestamp=1726381587 id_slot=0 id_task=0 p0=0
INFO [      log_server_request] request | tid="126086815940608" timestamp=1726381613 remote_addr="127.0.0.1" remote_port=59038 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086805454848" timestamp=1726381643 remote_addr="127.0.0.1" remote_port=35914 status=200 method="GET" path="/health" params={}
INFO [                 release] slot released | tid="126087453233152" timestamp=1726381666 id_slot=0 id_task=0 n_past=1011 truncated=false
INFO [           print_timings] prompt eval time     =   39264.22 ms /   685 tokens (   57.32 ms per token,    17.45 tokens per second) | tid="126087453233152" timestamp=1726381666 id_slot=0 id_task=0 t_prompt_processing=39264.217 n_prompt_tokens_processed=685 t_token=57.320024817518245 n_tokens_second=17.44591010181102
INFO [           print_timings] generation eval time =   40157.40 ms /   327 runs   (  122.81 ms per token,     8.14 tokens per second) | tid="126087453233152" timestamp=1726381666 id_slot=0 id_task=0 t_token_generation=40157.401 n_decoded=327 t_token=122.80550764525994 n_tokens_second=8.142957259609506
INFO [           print_timings]           total time =   79421.62 ms | tid="126087453233152" timestamp=1726381666 id_slot=0 id_task=0 t_prompt_processing=39264.217 t_token_generation=40157.401 t_total=79421.61799999999
INFO [            update_slots] all slots are idle | tid="126087453233152" timestamp=1726381666
INFO [      log_server_request] request | tid="126086904020992" timestamp=1726381666 remote_addr="10.147.20.194" remote_port=47472 status=200 method="POST" path="/v1/chat/completions" params={}
INFO [   launch_slot_with_task] slot is processing task | tid="126087453233152" timestamp=1726381670 id_slot=0 id_task=328
INFO [            update_slots] kv cache rm [p0, end) | tid="126087453233152" timestamp=1726381670 id_slot=0 id_task=328 p0=0
INFO [      log_server_request] request | tid="126086794969088" timestamp=1726381673 remote_addr="127.0.0.1" remote_port=44812 status=200 method="GET" path="/health" params={}
INFO [                 release] slot released | tid="126087453233152" timestamp=1726381696 id_slot=0 id_task=328 n_past=1011 truncated=false
INFO [           print_timings] prompt eval time     =    1319.62 ms /   685 tokens (    1.93 ms per token,   519.09 tokens per second) | tid="126087453233152" timestamp=1726381696 id_slot=0 id_task=328 t_prompt_processing=1319.625 n_prompt_tokens_processed=685 t_token=1.9264598540145985 n_tokens_second=519.0868617978592
INFO [           print_timings] generation eval time =   24725.42 ms /   327 runs   (   75.61 ms per token,    13.23 tokens per second) | tid="126087453233152" timestamp=1726381696 id_slot=0 id_task=328 t_token_generation=24725.416 n_decoded=327 t_token=75.61289296636086 n_tokens_second=13.225257767149397
INFO [           print_timings]           total time =   26045.04 ms | tid="126087453233152" timestamp=1726381696 id_slot=0 id_task=328 t_prompt_processing=1319.625 t_token_generation=24725.416 t_total=26045.041
INFO [            update_slots] all slots are idle | tid="126087453233152" timestamp=1726381696
INFO [      log_server_request] request | tid="126086904020992" timestamp=1726381696 remote_addr="10.147.20.194" remote_port=47472 status=200 method="POST" path="/v1/chat/completions" params={}
INFO [      log_server_request] request | tid="126086763511808" timestamp=1726381703 remote_addr="127.0.0.1" remote_port=57226 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086773997568" timestamp=1726381733 remote_addr="127.0.0.1" remote_port=58518 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086784483328" timestamp=1726381763 remote_addr="127.0.0.1" remote_port=36938 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086753026048" timestamp=1726381793 remote_addr="127.0.0.1" remote_port=34366 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086742540288" timestamp=1726381823 remote_addr="127.0.0.1" remote_port=36110 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086721568768" timestamp=1726381853 remote_addr="127.0.0.1" remote_port=41308 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086732054528" timestamp=1726381883 remote_addr="127.0.0.1" remote_port=44500 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086711083008" timestamp=1726381913 remote_addr="127.0.0.1" remote_port=51098 status=200 method="GET" path="/health" params={}
INFO [      log_server_request] request | tid="126086700597248" timestamp=1726381943 remote_addr="127.0.0.1" remote_port=39654 status=200 method="GET" path="/health" params={}

[squallliu]

The same problem exists, only cuda.

build: 583 (daa9623) with cc (Ubuntu 13.2.0-4ubuntu3) 13.2.0 for x86_64-linux-gnu
system info: n_threads = 64, n_threads_batch = 64, total_threads = 128

system_info: n_threads = 64 (n_threads_batch = 64) / 128 | AVX = 1 | AVX_VNNI = 0 | AVX2 = 1 | AVX512 = 0 | AVX512_VBMI = 0 | AVX512_VNNI = 0 | AVX512_BF16 = 0 | FMA = 1 | NEON = 0 | SVE = 0 | ARM_FMA = 0 | F16C = 1 | FP16_VA = 0 | RISCV_VECT = 0 | WASM_SIMD = 0 | BLAS = 1 | SSE3 = 1 | SSSE3 = 1 | VSX = 0 | MATMUL_INT8 = 0 | LLAMAFILE = 1 | 

main: HTTP server is listening, hostname: 0.0.0.0, port: 8080, http threads: 127
main: loading model
llama_model_loader: loaded meta data with 28 key-value pairs and 339 tensors from /app/ggml-model-Q8.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              = qwen2
llama_model_loader: - kv   1:                               general.type str              = model
llama_model_loader: - kv   2:                               general.name str              = Qwen2 7B Instruct
llama_model_loader: - kv   3:                           general.finetune str              = Instruct
llama_model_loader: - kv   4:                           general.basename str              = Qwen2
llama_model_loader: - kv   5:                         general.size_label str              = 7B
llama_model_loader: - kv   6:                            general.license str              = apache-2.0
llama_model_loader: - kv   7:                               general.tags arr[str,2]       = ["chat", "text-generation"]
llama_model_loader: - kv   8:                          general.languages arr[str,1]       = ["en"]
llama_model_loader: - kv   9:                          qwen2.block_count u32              = 28
llama_model_loader: - kv  10:                       qwen2.context_length u32              = 32768
llama_model_loader: - kv  11:                     qwen2.embedding_length u32              = 3584
llama_model_loader: - kv  12:                  qwen2.feed_forward_length u32              = 18944
llama_model_loader: - kv  13:                 qwen2.attention.head_count u32              = 28
llama_model_loader: - kv  14:              qwen2.attention.head_count_kv u32              = 4
llama_model_loader: - kv  15:                       qwen2.rope.freq_base f32              = 1000000.000000
llama_model_loader: - kv  16:     qwen2.attention.layer_norm_rms_epsilon f32              = 0.000001
llama_model_loader: - kv  17:                          general.file_type u32              = 7
llama_model_loader: - kv  18:                       tokenizer.ggml.model str              = gpt2
llama_model_loader: - kv  19:                         tokenizer.ggml.pre str              = qwen2
llama_model_loader: - kv  20:                      tokenizer.ggml.tokens arr[str,152064]  = ["!", "\"", "#", "$", "%", "&", "'", ...
llama_model_loader: - kv  21:                  tokenizer.ggml.token_type arr[i32,152064]  = [1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, ...
llama_model_loader: - kv  22:                      tokenizer.ggml.merges arr[str,151387]  = ["Ġ Ġ", "ĠĠ ĠĠ", "i n", "Ġ t",...
llama_model_loader: - kv  23:                tokenizer.ggml.eos_token_id u32              = 151645
llama_model_loader: - kv  24:            tokenizer.ggml.padding_token_id u32              = 151643
llama_model_loader: - kv  25:                tokenizer.ggml.bos_token_id u32              = 151643
llama_model_loader: - kv  26:                    tokenizer.chat_template str              = {% for message in messages %}{% if lo...
llama_model_loader: - kv  27:               general.quantization_version u32              = 2
llama_model_loader: - type  f32:  141 tensors
llama_model_loader: - type q8_0:  198 tensors
llm_load_vocab: special tokens cache size = 3
llm_load_vocab: token to piece cache size = 0.9308 MB
llm_load_print_meta: format           = GGUF V3 (latest)
llm_load_print_meta: arch             = qwen2
llm_load_print_meta: vocab type       = BPE
llm_load_print_meta: n_vocab          = 152064
llm_load_print_meta: n_merges         = 151387
llm_load_print_meta: vocab_only       = 0
llm_load_print_meta: n_ctx_train      = 32768
llm_load_print_meta: n_embd           = 3584
llm_load_print_meta: n_layer          = 28
llm_load_print_meta: n_head           = 28
llm_load_print_meta: n_head_kv        = 4
llm_load_print_meta: n_rot            = 128
llm_load_print_meta: n_swa            = 0
llm_load_print_meta: n_embd_head_k    = 128
llm_load_print_meta: n_embd_head_v    = 128
llm_load_print_meta: n_gqa            = 7
llm_load_print_meta: n_embd_k_gqa     = 512
llm_load_print_meta: n_embd_v_gqa     = 512
llm_load_print_meta: f_norm_eps       = 0.0e+00
llm_load_print_meta: f_norm_rms_eps   = 1.0e-06
llm_load_print_meta: f_clamp_kqv      = 0.0e+00
llm_load_print_meta: f_max_alibi_bias = 0.0e+00
llm_load_print_meta: f_logit_scale    = 0.0e+00
llm_load_print_meta: n_ff             = 18944
llm_load_print_meta: n_expert         = 0
llm_load_print_meta: n_expert_used    = 0
llm_load_print_meta: causal attn      = 1
llm_load_print_meta: pooling type     = 0
llm_load_print_meta: rope type        = 2
llm_load_print_meta: rope scaling     = linear
llm_load_print_meta: freq_base_train  = 1000000.0
llm_load_print_meta: freq_scale_train = 1
llm_load_print_meta: n_ctx_orig_yarn  = 32768
llm_load_print_meta: rope_finetuned   = unknown
llm_load_print_meta: ssm_d_conv       = 0
llm_load_print_meta: ssm_d_inner      = 0
llm_load_print_meta: ssm_d_state      = 0
llm_load_print_meta: ssm_dt_rank      = 0
llm_load_print_meta: ssm_dt_b_c_rms   = 0
llm_load_print_meta: model type       = ?B
llm_load_print_meta: model ftype      = Q8_0
llm_load_print_meta: model params     = 7.62 B
llm_load_print_meta: model size       = 7.54 GiB (8.50 BPW) 
llm_load_print_meta: general.name     = Qwen2 7B Instruct
llm_load_print_meta: BOS token        = 151643 '<|endoftext|>'
llm_load_print_meta: EOS token        = 151645 '<|im_end|>'
llm_load_print_meta: PAD token        = 151643 '<|endoftext|>'
llm_load_print_meta: LF token         = 148848 'ÄĬ'
llm_load_print_meta: EOT token        = 151645 '<|im_end|>'
llm_load_print_meta: max token length = 256
ggml_cuda_init: GGML_CUDA_FORCE_MMQ:    no
ggml_cuda_init: GGML_CUDA_FORCE_CUBLAS: no
ggml_cuda_init: found 2 CUDA devices:
  Device 0: NVIDIA L20, compute capability 8.9, VMM: yes
  Device 1: NVIDIA L20, compute capability 8.9, VMM: yes
llm_load_tensors: ggml ctx size =    0.30 MiB
llm_load_tensors: offloading 28 repeating layers to GPU
llm_load_tensors: offloading non-repeating layers to GPU
llm_load_tensors: offloaded 29/29 layers to GPU
llm_load_tensors:        CPU buffer size =   552.23 MiB
llm_load_tensors:      CUDA0 buffer size =  7165.44 MiB
........................................................................................
llama_new_context_with_model: n_ctx      = 32768
llama_new_context_with_model: n_batch    = 2048
llama_new_context_with_model: n_ubatch   = 512
llama_new_context_with_model: flash_attn = 1
llama_new_context_with_model: freq_base  = 1000000.0
llama_new_context_with_model: freq_scale = 1
llama_kv_cache_init:      CUDA0 KV buffer size =  1792.00 MiB
llama_new_context_with_model: KV self size  = 1792.00 MiB, K (f16):  896.00 MiB, V (f16):  896.00 MiB
llama_new_context_with_model:  CUDA_Host  output buffer size =     1.16 MiB
llama_new_context_with_model: pipeline parallelism enabled (n_copies=4)
llama_new_context_with_model:      CUDA0 compute buffer size =   595.02 MiB
llama_new_context_with_model:  CUDA_Host compute buffer size =   263.02 MiB
llama_new_context_with_model: graph nodes  = 875
llama_new_context_with_model: graph splits = 2
llama_init_from_gpt_params: warming up the model with an empty run - please wait ... (--no-warmup to disable)
srv          init: initializing slots, n_slots = 1
slot         init: id  0 | task -1 | new slot n_ctx_slot = 32768
main: model loaded
main: chat template, built_in: 1, chat_example: '<|im_start|>system
You are a helpful assistant<|im_end|>
<|im_start|>user
Hello<|im_end|>
<|im_start|>assistant
Hi there<|im_end|>
<|im_start|>user
How are you?<|im_end|>
<|im_start|>assistant

'main: server is listening on 0.0.0.0:8080 - starting the main loop
srv  update_slots: all slots are idle
slot launch_slot_: id  0 | task 0 | processing task
slot update_slots: id  0 | task 0 | tokenizing prompt, len = 1
slot update_slots: id  0 | task 0 | prompt tokenized, n_ctx_slot = 32768, n_keep = 0, n_prompt_tokens = 47
slot update_slots: id  0 | task 0 | kv cache rm [0, end)
slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 47, n_tokens = 47, progress = 1.000000
slot update_slots: id  0 | task 0 | prompt done, n_past = 47, n_tokens = 47
slot      release: id  0 | task 0 | stop processing: n_past = 129, truncated = 0
slot print_timing: id  0 | task 0 | 
prompt eval time =   27332.40 ms /    47 tokens (  581.54 ms per token,     1.72 tokens per second)
       eval time =   18716.43 ms /    83 tokens (  225.50 ms per token,     4.43 tokens per second)
      total time =   46048.83 ms /   130 tokens
srv  update_slots: all slots are idle
request: POST /v1/chat/completions
slot launch_slot_: id  0 | task 84 | processing task
slot update_slots: id  0 | task 84 | tokenizing prompt, len = 1
slot update_slots: id  0 | task 84 | prompt tokenized, n_ctx_slot = 32768, n_keep = 0, n_prompt_tokens = 47
slot update_slots: id  0 | task 84 | kv cache rm [0, end)
slot update_slots: id  0 | task 84 | prompt processing progress, n_past = 47, n_tokens = 47, progress = 1.000000
slot update_slots: id  0 | task 84 | prompt done, n_past = 47, n_tokens = 47
slot      release: id  0 | task 84 | stop processing: n_past = 122, truncated = 0
slot print_timing: id  0 | task 84 | 
prompt eval time =      23.07 ms /    47 tokens (    0.49 ms per token,  2037.19 tokens per second)
       eval time =     984.00 ms /    76 tokens (   12.95 ms per token,    77.24 tokens per second)
      total time =    1007.07 ms /   123 tokens
srv  update_slots: all slots are idle
request: POST /v1/chat/completions

[ngxson]

Could you try without CUDA graph? Set GGML_CUDA_DISABLE_GRAPHS=1

[marib00]

Doesn't seem to be making any difference:

>docker run -p 8080:8080 --name llama-server -v ~/gguf_models:/models --gpus all -e GGML_CUDA_DISABLE_GRAPHS=1 ghcr.io/ggerganov/llama.cpp:server-cuda -m models/Meta-Llama-3.1-70B-Instruct-Q4_K_L.gguf -c 65536 -fa --host 0.0.0.0 --port 8080 --n-gpu-layers 99 -ctk q4_0 -ctv q4_0 -t 4
warn: LLAMA_ARG_HOST environment variable is set, but will be overwritten by command line argument --host
build: 0 (unknown) with cc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0 for x86_64-linux-gnu
system info: n_threads = 4, n_threads_batch = 4, total_threads = 36

system_info: n_threads = 4 (n_threads_batch = 4) / 36 | AVX = 1 | AVX_VNNI = 0 | AVX2 = 1 | AVX512 = 0 | AVX512_VBMI = 0 | AVX512_VNNI = 0 | AVX512_BF16 = 0 | FMA = 1 | NEON = 0 | SVE = 0 | ARM_FMA = 0 | F16C = 1 | FP16_VA = 0 | RISCV_VECT = 0 | WASM_SIMD = 0 | BLAS = 1 | SSE3 = 1 | SSSE3 = 1 | VSX = 0 | MATMUL_INT8 = 0 | LLAMAFILE = 1 |

main: HTTP server is listening, hostname: 0.0.0.0, port: 8080, http threads: 35
main: loading model
llama_model_loader: loaded meta data with 33 key-value pairs and 724 tensors from models/Meta-Llama-3.1-70B-Instruct-Q4_K_L.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              = llama
llama_model_loader: - kv   1:                               general.type str              = model
llama_model_loader: - kv   2:                               general.name str              = Meta Llama 3.1 70B Instruct
llama_model_loader: - kv   3:                           general.finetune str              = Instruct
llama_model_loader: - kv   4:                           general.basename str              = Meta-Llama-3.1
llama_model_loader: - kv   5:                         general.size_label str              = 70B
llama_model_loader: - kv   6:                            general.license str              = llama3.1
llama_model_loader: - kv   7:                               general.tags arr[str,6]       = ["facebook", "meta", "pytorch", "llam...
llama_model_loader: - kv   8:                          general.languages arr[str,8]       = ["en", "de", "fr", "it", "pt", "hi", ...
llama_model_loader: - kv   9:                          llama.block_count u32              = 80
llama_model_loader: - kv  10:                       llama.context_length u32              = 131072
llama_model_loader: - kv  11:                     llama.embedding_length u32              = 8192
llama_model_loader: - kv  12:                  llama.feed_forward_length u32              = 28672
llama_model_loader: - kv  13:                 llama.attention.head_count u32              = 64
llama_model_loader: - kv  14:              llama.attention.head_count_kv u32              = 8
llama_model_loader: - kv  15:                       llama.rope.freq_base f32              = 500000.000000
llama_model_loader: - kv  16:     llama.attention.layer_norm_rms_epsilon f32              = 0.000010
llama_model_loader: - kv  17:                          general.file_type u32              = 15
llama_model_loader: - kv  18:                           llama.vocab_size u32              = 128256
llama_model_loader: - kv  19:                 llama.rope.dimension_count u32              = 128
llama_model_loader: - kv  20:                       tokenizer.ggml.model str              = gpt2
llama_model_loader: - kv  21:                         tokenizer.ggml.pre str              = llama-bpe
llama_model_loader: - kv  22:                      tokenizer.ggml.tokens arr[str,128256]  = ["!", "\"", "#", "$", "%", "&", "'", ...
llama_model_loader: - kv  23:                  tokenizer.ggml.token_type arr[i32,128256]  = [1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, 1, ...
llama_model_loader: - kv  24:                      tokenizer.ggml.merges arr[str,280147]  = ["Ġ Ġ", "Ġ ĠĠĠ", "ĠĠ ĠĠ", "...
llama_model_loader: - kv  25:                tokenizer.ggml.bos_token_id u32              = 128000
llama_model_loader: - kv  26:                tokenizer.ggml.eos_token_id u32              = 128009
llama_model_loader: - kv  27:                    tokenizer.chat_template str              = {{- bos_token }}\n{%- if custom_tools ...
llama_model_loader: - kv  28:               general.quantization_version u32              = 2
llama_model_loader: - kv  29:                      quantize.imatrix.file str              = /models_out/Meta-Llama-3.1-70B-Instru...
llama_model_loader: - kv  30:                   quantize.imatrix.dataset str              = /training_dir/calibration_datav3.txt
llama_model_loader: - kv  31:             quantize.imatrix.entries_count i32              = 560
llama_model_loader: - kv  32:              quantize.imatrix.chunks_count i32              = 125
llama_model_loader: - type  f32:  162 tensors
llama_model_loader: - type q8_0:    2 tensors
llama_model_loader: - type q4_K:  440 tensors
llama_model_loader: - type q5_K:   40 tensors
llama_model_loader: - type q6_K:   80 tensors
llm_load_vocab: special tokens cache size = 256
llm_load_vocab: token to piece cache size = 0.7999 MB
llm_load_print_meta: format           = GGUF V3 (latest)
llm_load_print_meta: arch             = llama
llm_load_print_meta: vocab type       = BPE
llm_load_print_meta: n_vocab          = 128256
llm_load_print_meta: n_merges         = 280147
llm_load_print_meta: vocab_only       = 0
llm_load_print_meta: n_ctx_train      = 131072
llm_load_print_meta: n_embd           = 8192
llm_load_print_meta: n_layer          = 80
llm_load_print_meta: n_head           = 64
llm_load_print_meta: n_head_kv        = 8
llm_load_print_meta: n_rot            = 128
llm_load_print_meta: n_swa            = 0
llm_load_print_meta: n_embd_head_k    = 128
llm_load_print_meta: n_embd_head_v    = 128
llm_load_print_meta: n_gqa            = 8
llm_load_print_meta: n_embd_k_gqa     = 1024
llm_load_print_meta: n_embd_v_gqa     = 1024
llm_load_print_meta: f_norm_eps       = 0.0e+00
llm_load_print_meta: f_norm_rms_eps   = 1.0e-05
llm_load_print_meta: f_clamp_kqv      = 0.0e+00
llm_load_print_meta: f_max_alibi_bias = 0.0e+00
llm_load_print_meta: f_logit_scale    = 0.0e+00
llm_load_print_meta: n_ff             = 28672
llm_load_print_meta: n_expert         = 0
llm_load_print_meta: n_expert_used    = 0
llm_load_print_meta: causal attn      = 1
llm_load_print_meta: pooling type     = 0
llm_load_print_meta: rope type        = 0
llm_load_print_meta: rope scaling     = linear
llm_load_print_meta: freq_base_train  = 500000.0
llm_load_print_meta: freq_scale_train = 1
llm_load_print_meta: n_ctx_orig_yarn  = 131072
llm_load_print_meta: rope_finetuned   = unknown
llm_load_print_meta: ssm_d_conv       = 0
llm_load_print_meta: ssm_d_inner      = 0
llm_load_print_meta: ssm_d_state      = 0
llm_load_print_meta: ssm_dt_rank      = 0
llm_load_print_meta: ssm_dt_b_c_rms   = 0
llm_load_print_meta: model type       = 70B
llm_load_print_meta: model ftype      = Q4_K - Medium
llm_load_print_meta: model params     = 70.55 B
llm_load_print_meta: model size       = 40.32 GiB (4.91 BPW)
llm_load_print_meta: general.name     = Meta Llama 3.1 70B Instruct
llm_load_print_meta: BOS token        = 128000 '<|begin_of_text|>'
llm_load_print_meta: EOS token        = 128009 '<|eot_id|>'
llm_load_print_meta: LF token         = 128 'Ä'
llm_load_print_meta: EOT token        = 128009 '<|eot_id|>'
llm_load_print_meta: max token length = 256
ggml_cuda_init: GGML_CUDA_FORCE_MMQ:    no
ggml_cuda_init: GGML_CUDA_FORCE_CUBLAS: no
ggml_cuda_init: found 1 CUDA devices:
  Device 0: NVIDIA RTX A6000, compute capability 8.6, VMM: yes
llm_load_tensors: ggml ctx size =    0.68 MiB
.llm_load_tensors: offloading 80 repeating layers to GPU
llm_load_tensors: offloading non-repeating layers to GPU
llm_load_tensors: offloaded 81/81 layers to GPU
llm_load_tensors:        CPU buffer size =  1064.62 MiB
llm_load_tensors:      CUDA0 buffer size = 40222.18 MiB
................................................................................................
llama_new_context_with_model: n_ctx      = 65536
llama_new_context_with_model: n_batch    = 2048
llama_new_context_with_model: n_ubatch   = 512
llama_new_context_with_model: flash_attn = 1
llama_new_context_with_model: freq_base  = 500000.0
llama_new_context_with_model: freq_scale = 1
llama_kv_cache_init:      CUDA0 KV buffer size =  5760.00 MiB
llama_new_context_with_model: KV self size  = 5760.00 MiB, K (q4_0): 2880.00 MiB, V (q4_0): 2880.00 MiB
llama_new_context_with_model:  CUDA_Host  output buffer size =     0.98 MiB
llama_new_context_with_model:      CUDA0 compute buffer size =   266.50 MiB
llama_new_context_with_model:  CUDA_Host compute buffer size =   144.01 MiB
llama_new_context_with_model: graph nodes  = 2247
llama_new_context_with_model: graph splits = 2
llama_init_from_gpt_params: warming up the model with an empty run - please wait ... (--no-warmup to disable)
srv          init: initializing slots, n_slots = 1
slot         init: id  0 | task -1 | new slot n_ctx_slot = 65536
main: model loaded
main: chat template, built_in: 1, chat_example: '<|start_header_id|>system<|end_header_id|>

You are a helpful assistant<|eot_id|><|start_header_id|>user<|end_header_id|>

Hello<|eot_id|><|start_header_id|>assistant<|end_header_id|>

Hi there<|eot_id|><|start_header_id|>user<|end_header_id|>

How are you?<|eot_id|><|start_header_id|>assistant<|end_header_id|>


'main: server is listening on 0.0.0.0:8080 - starting the main loop
srv  update_slots: all slots are idle
request: GET /health 127.0.0.1 200
request: GET /health 127.0.0.1 200
request: GET /health 127.0.0.1 200
slot launch_slot_: id  0 | task 0 | processing task
slot update_slots: id  0 | task 0 | tokenizing prompt, len = 1
slot update_slots: id  0 | task 0 | prompt tokenized, n_ctx_slot = 65536, n_keep = 0, n_prompt_tokens = 685
slot update_slots: id  0 | task 0 | kv cache rm [0, end)
slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 685, n_tokens = 685, progress = 1.000000
slot update_slots: id  0 | task 0 | prompt done, n_past = 685, n_tokens = 685
request: GET /health 127.0.0.1 200
request: GET /health 127.0.0.1 200
slot      release: id  0 | task 0 | stop processing: n_past = 1011, truncated = 0
slot print_timing: id  0 | task 0 |
prompt eval time =   39939.65 ms /   685 tokens (   58.31 ms per token,    17.15 tokens per second)
       eval time =   41044.47 ms /   327 tokens (  125.52 ms per token,     7.97 tokens per second)
      total time =   80984.12 ms /  1012 tokens
srv  update_slots: all slots are idle
request: POST /v1/chat/completions 10.147.20.194 200
request: GET /health 127.0.0.1 200
request: GET /health 127.0.0.1 200

[ggerganov]

Has this started happening recently? Does it happen without docker?

I can't reproduce on my CUDA workstation.

[bosmart]

Happens both with and without docker. I wasn't using llama-server before so can't say if it's new or not.

[ggerganov]

Hm, does adding --no-mmap help?

[bosmart]

Doesn't help unfortunately.

[ngxson]

@ggerganov I was able to reproduce the problem on HF endpoints with A10G GPU (I didn't notice this issue before).

The first llama_decode takes ~20s, you can see the delay between decoding batch and next token in the log below.

Here is the log with --verbose. Sorry I don't have a build with LLAMA_DEBUG=1, so please test it if you can.

[ggerganov]

I just had it happen on an A10 machine as well using llama-bench. 1 CPU core was at 100% and the GPU was idle. Waited for 2-3 minutes and killed the process. Next runs were normal and didn't happen again.

[bosmart]

Still happens for me every time when using the docker image but not when I build from source (even when building from source inside a docker container).

[ggerganov]

Happened on my RTX 2060 workstation using the following commands:

GGML_CUDA=1 make -j && ./llama-server --host 0.0.0.0 --port 7020 --alias Meta-Llama-3.1-8B-Instruct-GGUF-Q6_K_L --gpu-layers 33 --model ~/Meta-Llama-3.1-8B-Instruct-Q6_K_L.gguf --threads-http 1 --ctx-size 1024 --metrics --chat-template llama3 --verbose

curl -s --request POST --url http://127.0.0.1:7020/v1/chat/completions --header "Content-Type: application/json" --data '{"messages": [ { "role": "system", "content": "You are a helpful assistant." }, { "role": "user", "content": "Hello, how are you today?" } ], "n_predict": 512}' | jq

Here is the log where the first decode takes ~8s:

0.25.727.078 I slot update_slots: id  0 | task 0 | kv cache rm [0, end)
0.25.727.086 I slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 28, n_tokens = 28, progress = 1.000000
0.25.727.089 I slot update_slots: id  0 | task 0 | prompt done, n_past = 28, n_tokens = 28
0.25.727.089 D srv  update_slots: decoding batch, n_tokens = 28
0.33.928.787 D slot process_toke: id  0 | task 0 | n_decoded = 1, n_remaining = 511, next token: 'I'
0.33.928.791 D srv  update_slots: run slots completed
0.33.928.791 D que    start_loop: waiting for new tasks

0.00.359.190 I ggml_cuda_init: GGML_CUDA_FORCE_MMQ:    no
0.00.359.192 I ggml_cuda_init: GGML_CUDA_FORCE_CUBLAS: no
0.00.359.193 I ggml_cuda_init: found 1 CUDA devices:
0.00.362.168 I   Device 0: NVIDIA GeForce RTX 2060 SUPER, compute capability 7.5, VMM: yes
0.00.490.706 I llm_load_tensors: ggml ctx size =    0.27 MiB
0.00.910.535 I llm_load_tensors: offloading 32 repeating layers to GPU
0.00.910.539 I llm_load_tensors: offloading non-repeating layers to GPU
0.00.910.539 I llm_load_tensors: offloaded 33/33 layers to GPU
0.00.910.545 I llm_load_tensors:        CPU buffer size =   532.31 MiB
0.00.910.545 I llm_load_tensors:      CUDA0 buffer size =  5993.34 MiB
......................................................................................
0.01.735.246 I llama_new_context_with_model: n_ctx      = 1024
0.01.735.248 I llama_new_context_with_model: n_batch    = 1024
0.01.735.249 I llama_new_context_with_model: n_ubatch   = 512
0.01.735.249 I llama_new_context_with_model: flash_attn = 0
0.01.735.253 I llama_new_context_with_model: freq_base  = 500000.0
0.01.735.254 I llama_new_context_with_model: freq_scale = 1
0.01.735.826 I llama_kv_cache_init:      CUDA0 KV buffer size =   128.00 MiB
0.01.735.830 I llama_new_context_with_model: KV self size  =  128.00 MiB, K (f16):   64.00 MiB, V (f16):   64.00 MiB
0.01.736.939 I llama_new_context_with_model:  CUDA_Host  output buffer size =     0.98 MiB
0.01.742.493 I llama_new_context_with_model:      CUDA0 compute buffer size =   258.50 MiB
0.01.742.497 I llama_new_context_with_model:  CUDA_Host compute buffer size =    10.01 MiB
0.01.742.497 I llama_new_context_with_model: graph nodes  = 1030
0.01.742.497 I llama_new_context_with_model: graph splits = 2
0.01.742.499 W llama_init_from_gpt_params: warming up the model with an empty run - please wait ... (--no-warmup to disable)
0.01.811.008 I srv          init: initializing slots, n_slots = 1
0.01.811.012 I slot         init: id  0 | task -1 | new slot n_ctx_slot = 1024
0.01.811.015 D slot        reset: id  0 | task -1 | 
0.01.811.095 I main: model loaded
0.01.811.112 I main: chat template, built_in: 0, chat_example: '<|start_header_id|>system<|end_header_id|>

You are a helpful assistant<|eot_id|><|start_header_id|>user<|end_header_id|>

Hello<|eot_id|><|start_header_id|>assistant<|end_header_id|>

Hi there<|eot_id|><|start_header_id|>user<|end_header_id|>

How are you?<|eot_id|><|start_header_id|>assistant<|end_header_id|>

'
0.01.811.112 I main: server is listening on 0.0.0.0:7020 - starting the main loop
0.01.811.113 D que    start_loop: processing new tasks
0.01.811.113 D que    start_loop: update slots
0.01.811.114 I srv  update_slots: all slots are idle
0.01.811.114 D srv  kv_cache_cle: clearing KV cache
0.01.811.430 D que    start_loop: waiting for new tasks
0.25.726.656 D formatted_chat: '<|start_header_id|>system<|end_header_id|>

You are a helpful assistant.<|eot_id|><|start_header_id|>user<|end_header_id|>

Hello, how are you today?<|eot_id|><|start_header_id|>assistant<|end_header_id|>

'
0.25.726.673 D srv  add_waiting_: add task 0 to waiting list. current waiting = 0 (before add)
0.25.726.674 D que          post: new task, id = 0/1, front = 0
0.25.726.981 D que    start_loop: processing new tasks
0.25.726.987 D que    start_loop: processing task, id = 0
0.25.726.990 D slot get_availabl: id  0 | task -1 | selected slot by lru, t_last = -1
0.25.726.991 D slot        reset: id  0 | task -1 | 
0.25.727.011 I slot launch_slot_: id  0 | task 0 | processing task
0.25.727.013 D que    start_loop: update slots
0.25.727.013 D srv  update_slots: posting NEXT_RESPONSE
0.25.727.014 D que          post: new task, id = 1, front = 0
0.25.727.016 I slot update_slots: id  0 | task 0 | tokenizing prompt, len = 1
0.25.727.069 I slot update_slots: id  0 | task 0 | prompt tokenized, n_ctx_slot = 1024, n_keep = 0, n_prompt_tokens = 28
0.25.727.078 I slot update_slots: id  0 | task 0 | kv cache rm [0, end)
0.25.727.086 I slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 28, n_tokens = 28, progress = 1.000000
0.25.727.089 I slot update_slots: id  0 | task 0 | prompt done, n_past = 28, n_tokens = 28
0.25.727.089 D srv  update_slots: decoding batch, n_tokens = 28
0.33.928.787 D slot process_toke: id  0 | task 0 | n_decoded = 1, n_remaining = 511, next token: 'I'
0.33.928.791 D srv  update_slots: run slots completed
0.33.928.791 D que    start_loop: waiting for new tasks
0.33.928.792 D que    start_loop: processing new tasks
0.33.928.793 D que    start_loop: processing task, id = 1
0.33.928.793 D que    start_loop: update slots
0.33.928.794 D srv  update_slots: posting NEXT_RESPONSE
0.33.928.795 D que          post: new task, id = 2, front = 0
0.33.928.796 D slot update_slots: id  0 | task 0 | slot decode token, n_ctx = 1024, n_past = 29, n_system_tokens = 0, n_cache_tokens = 0, truncated = 0
0.33.928.797 D srv  update_slots: decoding batch, n_tokens = 1
0.33.952.647 D slot process_toke: id  0 | task 0 | n_decoded = 2, n_remaining = 510, next token: ''m'
0.33.952.649 D srv  update_slots: run slots completed
0.33.952.650 D que    start_loop: waiting for new tasks
0.33.952.650 D que    start_loop: processing new tasks
0.33.952.650 D que    start_loop: processing task, id = 2
0.33.952.650 D que    start_loop: update slots
0.33.952.650 D srv  update_slots: posting NEXT_RESPONSE
0.33.952.651 D que          post: new task, id = 3, front = 0
0.33.952.652 D slot update_slots: id  0 | task 0 | slot decode token, n_ctx = 1024, n_past = 30, n_system_tokens = 0, n_cache_tokens = 0, truncated = 0
0.33.952.652 D srv  update_slots: decoding batch, n_tokens = 1
0.33.976.285 D slot process_toke: id  0 | task 0 | n_decoded = 3, n_remaining = 509, next token: ' doing'

After that, tried to restart the server and submit the same query many times but the first decode was always fast as expected:

0.04.133.752 I slot update_slots: id  0 | task 0 | kv cache rm [0, end)
0.04.133.758 I slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 28, n_tokens = 28, progress = 1.000000
0.04.133.759 I slot update_slots: id  0 | task 0 | prompt done, n_past = 28, n_tokens = 28
0.04.133.759 D srv  update_slots: decoding batch, n_tokens = 28
0.04.204.428 D slot process_toke: id  0 | task 0 | n_decoded = 1, n_remaining = 511, next token: 'I'
0.04.204.430 D srv  update_slots: run slots completed
0.04.204.431 D que    start_loop: waiting for new tasks