Performance regression between 0.7.4 and 0.9.0

[jeffmaury]

Issue Description

While working on an Podman AI Lab workflow to automate the update of ramalama version used in Podman AI Lab, I noticed, when switching from 0.7.4 to 0.9.0 a big performance drop in my validation tests:

Here are the logs from the server in the 2 configurations:

0.7.4:

prompt eval time = 3058.24 ms / 64 tokens ( 47.78 ms per token, 20.93 tokens per second)
eval time = 83033.60 ms / 455 tokens ( 182.49 ms per token, 5.48 tokens per second)
total time = 86091.84 ms / 519 tokens

0.9.0:
prompt eval time = 121635.23 ms / 64 tokens ( 1900.55 ms per token, 0.53 tokens per second)
eval time = 15152.22 ms / 93 tokens ( 162.93 ms per token, 6.14 tokens per second)
total time = 136787.44 ms / 157 tokens
srv update_slots: all slots are idle

Steps to reproduce the issue

Need Podman AI Lab dev and modifying the image reference in the code

Describe the results you received

See above

Describe the results you expected

Similar performance numbers

ramalama info output

N/A

Upstream Latest Release

Yes

Additional environment details

No response

Additional information

No response

[jeffmaury]

@bmahabirbu (FYI)

[jeffmaury]

Seems to happen when no system prompt is being sent in the request

[kpouget]

@jeffmaury , can you lookup in the logs the GGML backend being used, in both cases?
GPU acceleration, or CPU only?

[jeffmaury]

@jeffmaury , can you lookup in the logs the GGML backend being used, in both cases?
GPU acceleration, or CPU only?

CPU on Windows

[igsilya]

I can confirm that after upgrading from v0.8.5 to v0.9.0 the prompt evaluation times skyrocketed. CPU-only on Linux.
The difference AFAICT is that v0.9.0 identifies CPU as a vulkan device and so a vulkan core is used for processing instead of CPU-optimized. This also prevents using more than ~20K context as vulkan fails to allocate more than 2GB buffer.

v0.8.5:

build: 5335 (d8919424) with cc (GCC) 11.5.0 20240719 (Red Hat 11.5.0-5) for x86_64-redhat-linux                                        
system info: n_threads = 56, n_threads_batch = 56, total_threads = 56
                                                                                                                                       
system_info: n_threads = 56 (n_threads_batch = 56) / 56 | CPU : SSE3 = 1 | SSSE3 = 1 | AVX = 1 | AVX2 = 1 | F16C = 1 | FMA = 1 | BMI2 = 1 | LLAMAFILE = 1 | OPENMP = 1 | AARCH64_REPACK = 1 | 
...
load_tensors: loading model tensors, this can take a while... (mmap = true)
load_tensors: offloading 0 repeating layers to GPU
load_tensors: offloaded 0/41 layers to GPU
load_tensors:   CPU_Mapped model buffer size =  1463.05 MiB
load_tensors:  CPU_AARCH64 model buffer size =  1113.75 MiB
................................................................................................
llama_context: constructing llama_context
llama_context: n_seq_max     = 1                                   
llama_context: n_ctx         = 20000  
llama_context: n_ctx_per_seq = 20000                               
llama_context: n_batch       = 2048  
llama_context: n_ubatch      = 512 
llama_context: causal_attn   = 1                                   
llama_context: flash_attn    = 0                                   
llama_context: freq_base     = 10000000.0                          
llama_context: freq_scale    = 1                                   
llama_context: n_ctx_per_seq (20000) < n_ctx_train (131072) -- the full capacity of the model will not be utilized
llama_context:        CPU  output buffer size =     0.19 MiB       
llama_kv_cache_unified: kv_size = 20000, type_k = 'f16', type_v = 'f16', n_layer = 40, can_shift = 1, padding = 32
llama_kv_cache_unified:        CPU KV buffer size =  1562.50 MiB
llama_kv_cache_unified: KV self size  = 1562.50 MiB, K (f16):  781.25 MiB, V (f16):  781.25 MiB
llama_context:        CPU compute buffer size =  1305.07 MiB
llama_context: graph nodes  = 1448
llama_context: graph splits = 1
...
slot launch_slot_: id  0 | task 0 | processing task
slot update_slots: id  0 | task 0 | new prompt, n_ctx_slot = 20000, n_keep = 0, n_prompt_tokens = 971
slot update_slots: id  0 | task 0 | kv cache rm [0, end)
slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 971, n_tokens = 971, progress = 1.000000
slot update_slots: id  0 | task 0 | prompt done, n_past = 971, n_tokens = 971
slot      release: id  0 | task 0 | stop processing: n_past = 1005, truncated = 0
slot print_timing: id  0 | task 0 |
prompt eval time =    6013.42 ms /   971 tokens (    6.19 ms per token,   161.47 tokens per second)
       eval time =    1145.96 ms /    35 tokens (   32.74 ms per token,    30.54 tokens per second)
      total time =    7159.38 ms /  1006 tokens

Same exact thing on v0.9.0:

ggml_vulkan: Found 1 Vulkan devices:                                                                                                                                                                                                                                          
ggml_vulkan: 0 = llvmpipe (LLVM 19.1.7, 256 bits) (llvmpipe) | uma: 0 | fp16: 1 | warp size: 8 | shared memory: 32768 | int dot: 0 | matrix cores: none                                                                                                                       
ggml_vulkan: Warning: Device type is CPU. This is probably not the device you want.                                                    
build: 5499 (4265a87b) with cc (GCC) 11.5.0 20240719 (Red Hat 11.5.0-5) for x86_64-redhat-linux                                        
system info: n_threads = 56, n_threads_batch = 56, total_threads = 56                                                                  
                                                                   
system_info: n_threads = 56 (n_threads_batch = 56) / 56 | CPU : SSE3 = 1 | SSSE3 = 1 | AVX = 1 | AVX2 = 1 | F16C = 1 | FMA = 1 | BMI2 = 1 | LLAMAFILE = 1 | OPENMP = 1 | AARCH64_REPACK = 1 |                                                                                 
...
load_tensors: loading model tensors, this can take a while... (mmap = true)      
load_tensors: offloading 0 repeating layers to GPU                 
load_tensors: offloaded 0/41 layers to GPU                         
load_tensors:   CPU_Mapped model buffer size =  1472.05 MiB  
................................................................................................
llama_context: constructing llama_context
llama_context: n_seq_max     = 1                                   
llama_context: n_ctx         = 20000
llama_context: n_ctx_per_seq = 20000
llama_context: n_batch       = 2048
llama_context: n_ubatch      = 512
llama_context: causal_attn   = 1                                   
llama_context: flash_attn    = 0                                   
llama_context: freq_base     = 10000000.0
llama_context: freq_scale    = 1                                   
llama_context: n_ctx_per_seq (20000) < n_ctx_train (131072) -- the full capacity of the model will not be utilized
llama_context:        CPU  output buffer size =     0.19 MiB
llama_kv_cache_unified:        CPU KV buffer size =  1562.50 MiB
llama_kv_cache_unified: size = 1562.50 MiB ( 20000 cells,  40 layers,  1 seqs), K (f16):  781.25 MiB, V (f16):  781.25 MiB
llama_context:    Vulkan0 compute buffer size =  1346.38 MiB
llama_context: Vulkan_Host compute buffer size =    43.07 MiB
llama_context: graph nodes  = 1528
llama_context: graph splits = 444 (with bs=512), 1 (with bs=1)
...
slot launch_slot_: id  0 | task 0 | processing task
slot update_slots: id  0 | task 0 | new prompt, n_ctx_slot = 20000, n_keep = 0, n_prompt_tokens = 971
slot update_slots: id  0 | task 0 | kv cache rm [0, end)
slot update_slots: id  0 | task 0 | prompt processing progress, n_past = 971, n_tokens = 971, progress = 1.000000
slot update_slots: id  0 | task 0 | prompt done, n_past = 971, n_tokens = 971
slot      release: id  0 | task 0 | stop processing: n_past = 1003, truncated = 0
slot print_timing: id  0 | task 0 | 
prompt eval time =  273277.60 ms /   971 tokens (  281.44 ms per token,     3.55 tokens per second)
       eval time =    1584.34 ms /    33 tokens (   48.01 ms per token,    20.83 tokens per second)
      total time =  274861.94 ms /  1004 tokens

As you can see, the prompt eval went down from 160 to just 3 tokens per second.
Unfortunately, we really want tool call streaming, so can't use 0.8.5.

[kpouget]

yes, looks like ggml-vulkan detects that it's running on CPU ... but still loads :/

ggml_vulkan: Found 1 Vulkan devices:                                                                                                                                                                                                                                          
ggml_vulkan: 0 = llvmpipe (LLVM 19.1.7, 256 bits) (llvmpipe) | uma: 0 | fp16: 1 | warp size: 8 | shared memory: 32768 | int dot: 0 | matrix cores: none                                                                                                                       
ggml_vulkan: Warning: Device type is CPU. This is probably not the device you want.                        

warning is coming from there:

    if (props2.properties.deviceType == vk::PhysicalDeviceType::eCpu) {
        GGML_LOG_DEBUG("ggml_vulkan: Warning: Device type is CPU. This is probably not the device you want.\n");
    }

[kpouget]

I've already noticed that Vulkan exposes more "devices" that there actually are, including this one:

$ vulkaninfo --summary
GPU3:
	apiVersion         = 1.3.278
	driverVersion      = 0.0.1
	vendorID           = 0x10005
	deviceID           = 0x0000
	deviceType         = PHYSICAL_DEVICE_TYPE_CPU
	deviceName         = llvmpipe (LLVM 18.1.8, 128 bits)
	driverID           = DRIVER_ID_MESA_LLVMPIPE
	driverName         = llvmpipe
	driverInfo         = Mesa 24.1.2 (LLVM 18.1.8)
	conformanceVersion = 1.3.1.1
	deviceUUID         = 6d657361-3234-2e31-2e32-000000000000
	driverUUID         = 6c6c766d-7069-7065-5555-494400000000

which is making trouble here :/

[rhatdan]

You can pull the previous image with --image quay.io/ramalama/ramalama:0.8

@slp @ericcurtin @ggerganov how should we handle this?

[igsilya]

You can pull the previous image with --image quay.io/ramalama/ramalama:0.8

We need 0.9 for tool streaming. But yes, if someone doesn't need new features they can use older image as a workaround.

[igsilya]

Another workaround is to re-build images locally with the following change:

diff --git a/container-images/scripts/build_llama_and_whisper.sh b/container-images/scripts/build_llama_and_whisper.sh
index 8dd7bcc..6599507 100755
--- a/container-images/scripts/build_llama_and_whisper.sh
+++ b/container-images/scripts/build_llama_and_whisper.sh
@@ -230,7 +230,7 @@ configure_common_flags() {
     common_flags+=("-DGGML_CUDA=ON" "-DCMAKE_EXE_LINKER_FLAGS=-Wl,--allow-shlib-undefined" "-DCMAKE_CUDA_FLAGS=\"-U__ARM_NEON -U__ARM_NEON__\"")
     ;;
   vulkan | asahi)
-    common_flags+=("-DGGML_VULKAN=1")
+    common_flags+=("-DGGML_VULKAN=OFF")
     ;;
   intel-gpu)
     common_flags+=("-DGGML_SYCL=ON" "-DCMAKE_C_COMPILER=icx" "-DCMAKE_CXX_COMPILER=icpx")
@@ -321,7 +321,7 @@ main() {
   case "$containerfile" in
   ramalama)
     if [ "$uname_m" = "x86_64" ] || [ "$uname_m" = "aarch64" ]; then
-      common_flags+=("-DGGML_VULKAN=ON")
+      common_flags+=("-DGGML_VULKAN=OFF")
     elif [ "$uname_m" = "s390x" ]; then
       common_flags+=("-DGGML_VXE=ON" "-DGGML_BLAS=ON" "-DGGML_BLAS_VENDOR=OpenBLAS")
     fi

This restores the performance as there is no vulkan anymore. (not sure if the OFF switch is necessary in both places, but I replaced all that I found without thinking too much.)

One solution for ramalama, I suppose, is to ship a separate CPU-only image.

[rhatdan]

Does passing --ngl=0 improve the performance?

[igsilya]

Does passing --ngl=0 improve the performance?

Nope. ngl option has no effect. Still runs vulkan on CPU.

[bmahabirbu]

I tested this on my Cuda machine with the Vulkan image (but using cpu only) and can confirm that the performance is very slow, which is odd as the previous Vulkan image before this one was not causing the issue.

One very interesting thing I noticed is that if you remove -ngl entirely, the first prompt takes a while to load, but subsequent prompts are speedy

first one

prompt eval time =   40096.60 ms /   111 tokens (  361.23 ms per token,     2.77 tokens per second)**
       eval time =     556.76 ms /    13 tokens (   42.83 ms per token,    23.35 tokens per second)
      total time =   40653.35 ms /   124 tokens

second one

prompt eval time =     179.57 ms /    14 tokens (   12.83 ms per token,    77.96 tokens per second)**
       eval time =    1930.50 ms /    39 tokens (   49.50 ms per token,    20.20 tokens per second)
      total time =    2110.07 ms /    53 tokens

[bmahabirbu]

Update! Removing -ngl , --flash-attn, and --jinja Fixes the issue for pure CPU inference on the vulkan image

I don't know why including the removal of Jinja specifically fixed this, but it seems specifying any arguments that relate to GPU causes the delay, which includes ngl and flash attention. ngl=0 doesnt help here so it seems even with it being 0 some gpu usage is taking place

We need Jinja for tool calling so this cant be removed as a quick fix