Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: Detokenize delay when update vllm from 0.3.0 to 0.4.2 #5206

Closed
DriverSong opened this issue Jun 3, 2024 · 1 comment · Fixed by #5207
Closed

[Bug]: Detokenize delay when update vllm from 0.3.0 to 0.4.2 #5206

DriverSong opened this issue Jun 3, 2024 · 1 comment · Fixed by #5207
Labels
bug Something isn't working

Comments

@DriverSong
Copy link
Contributor

Your current environment

Collecting environment information...
PyTorch version: 2.3.0+cu121
Is debug build: False
CUDA used to build PyTorch: 12.1
ROCM used to build PyTorch: N/A

OS: CentOS Linux 7 (Core) (x86_64)
GCC version: (GCC) 9.3.1 20200408 (Red Hat 9.3.1-2)
Clang version: 3.4.2 (tags/RELEASE_34/dot2-final)
CMake version: version 3.29.3
Libc version: glibc-2.17

Python version: 3.10.12 (main, Jul  5 2023, 18:54:27) [GCC 11.2.0] (64-bit runtime)
Python platform: Linux-4.18.0-193.28.1.el8_2.x86_64-x86_64-with-glibc2.17
Is CUDA available: True
CUDA runtime version: 12.1.105
CUDA_MODULE_LOADING set to: LAZY
GPU models and configuration:
GPU 0: NVIDIA A800-SXM4-80GB
GPU 1: NVIDIA A800-SXM4-80GB

Nvidia driver version: 525.125.06
cuDNN version: Probably one of the following:
/usr/lib64/libcudnn.so.8.0.5
/usr/lib64/libcudnn_adv_infer.so.8.0.5
/usr/lib64/libcudnn_adv_train.so.8.0.5
/usr/lib64/libcudnn_cnn_infer.so.8.0.5
/usr/lib64/libcudnn_cnn_train.so.8.0.5
/usr/lib64/libcudnn_ops_infer.so.8.0.5
/usr/lib64/libcudnn_ops_train.so.8.0.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn.so.8.9.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn_adv_infer.so.8.9.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn_adv_train.so.8.9.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn_cnn_infer.so.8.9.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn_cnn_train.so.8.9.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn_ops_infer.so.8.9.5
/usr/local/cuda/targets/x86_64-linux/lib/libcudnn_ops_train.so.8.9.5
HIP runtime version: N/A
MIOpen runtime version: N/A
Is XNNPACK available: True

CPU:
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                128
On-line CPU(s) list:   0-127
Thread(s) per core:    2
Core(s) per socket:    32
Socket(s):             2
NUMA node(s):          2
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 106
Model name:            Intel(R) Xeon(R) Platinum 8338C CPU @ 2.60GHz
Stepping:              6
CPU MHz:               3077.183
CPU max MHz:           3500.0000
CPU min MHz:           800.0000
BogoMIPS:              5200.00
Virtualization:        VT-x
L1d cache:             48K
L1i cache:             32K
L2 cache:              1280K
L3 cache:              49152K
NUMA node0 CPU(s):     0-31,64-95
NUMA node1 CPU(s):     32-63,96-127
Flags:                 fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx smx est tm2 ssse3 sdbg fma cx16 xtpr pdcm pcid dca sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb cat_l3 invpcid_single ssbd mba ibrs ibpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid fsgsbase tsc_adjust bmi1 hle avx2 smep bmi2 erms invpcid rtm cqm rdt_a avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb intel_pt avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves cqm_llc cqm_occup_llc cqm_mbm_total cqm_mbm_local wbnoinvd dtherm ida arat pln pts hwp hwp_act_window hwp_epp hwp_pkg_req avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg tme avx512_vpopcntdq la57 rdpid md_clear pconfig flush_l1d arch_capabilities

Versions of relevant libraries:
[pip3] numpy==1.26.4
[pip3] nvidia-nccl-cu12==2.20.5
[pip3] torch==2.3.0
[pip3] torchaudio==2.3.0
[pip3] torchvision==0.18.0
[pip3] triton==2.3.0
[pip3] vllm-nccl-cu12==2.18.1.0.4.0
[conda] numpy                     1.26.4                   pypi_0    pypi
[conda] nvidia-nccl-cu12          2.20.5                   pypi_0    pypi
[conda] torch                     2.3.0                    pypi_0    pypi
[conda] torchaudio                2.3.0                    pypi_0    pypi
[conda] torchvision               0.18.0                   pypi_0    pypi
[conda] triton                    2.3.0                    pypi_0    pypi
[conda] vllm-nccl-cu12            2.18.1.0.4.0             pypi_0    pypiROCM Version: Could not collect
Neuron SDK Version: N/A
vLLM Version: 0.4.2
vLLM Build Flags:
CUDA Archs: Not Set; ROCm: Disabled; Neuron: Disabled
GPU Topology:
GPU0    GPU1    NIC0    NIC1    NIC2    NIC3    NIC4    NIC5    NIC6    NIC7    NIC8    NIC9    NIC10   CPU Affinity    NUMA Affinity
GPU0     X      NV8     SYS     SYS     SYS     SYS     SYS     SYS     NODE    NODE    PXB     PXB     SYS     32-63,96-127    1
GPU1    NV8      X      SYS     SYS     SYS     SYS     SYS     SYS     NODE    NODE    PXB     PXB     SYS     32-63,96-127    1
NIC0    SYS     SYS      X      PIX     NODE    NODE    NODE    NODE    SYS     SYS     SYS     SYS     NODE
NIC1    SYS     SYS     PIX      X      NODE    NODE    NODE    NODE    SYS     SYS     SYS     SYS     NODE
NIC2    SYS     SYS     NODE    NODE     X      PIX     NODE    NODE    SYS     SYS     SYS     SYS     NODE
NIC3    SYS     SYS     NODE    NODE    PIX      X      NODE    NODE    SYS     SYS     SYS     SYS     NODE
NIC4    SYS     SYS     NODE    NODE    NODE    NODE     X      PIX     SYS     SYS     SYS     SYS     NODE
NIC5    SYS     SYS     NODE    NODE    NODE    NODE    PIX      X      SYS     SYS     SYS     SYS     NODE
NIC6    NODE    NODE    SYS     SYS     SYS     SYS     SYS     SYS      X      PIX     NODE    NODE    SYS
NIC7    NODE    NODE    SYS     SYS     SYS     SYS     SYS     SYS     PIX      X      NODE    NODE    SYS
NIC8    PXB     PXB     SYS     SYS     SYS     SYS     SYS     SYS     NODE    NODE     X      PIX     SYS
NIC9    PXB     PXB     SYS     SYS     SYS     SYS     SYS     SYS     NODE    NODE    PIX      X      SYS
NIC10   SYS     SYS     NODE    NODE    NODE    NODE    NODE    NODE    SYS     SYS     SYS     SYS      X

Legend:

  X    = Self
  SYS  = Connection traversing PCIe as well as the SMP interconnect between NUMA nodes (e.g., QPI/UPI)
  NODE = Connection traversing PCIe as well as the interconnect between PCIe Host Bridges within a NUMA node
  PHB  = Connection traversing PCIe as well as a PCIe Host Bridge (typically the CPU)
  PXB  = Connection traversing multiple PCIe bridges (without traversing the PCIe Host Bridge)
  PIX  = Connection traversing at most a single PCIe bridge
  NV#  = Connection traversing a bonded set of # NVLinks

NIC Legend:

  NIC0: mlx5_2
  NIC1: mlx5_3
  NIC2: mlx5_4
  NIC3: mlx5_5
  NIC4: mlx5_6
  NIC5: mlx5_7
  NIC6: mlx5_8
  NIC7: mlx5_9
  NIC8: mlx5_10
  NIC9: mlx5_11
  NIC10: mlx5_bond_0

🐛 Describe the bug

I updated the vllm from 0.3.0 to 0.4.2, both are offical release, while the generation time increased from 45 seconds to 50 minutes on qwen1.5-0.5B model with the AdvertiseGen dataset.

After compared each phase of generation between the two release version, I found out that the main delay was caused by the function detokenize_incrementally in vllm.transformers_utils.detokenizer.py.
I added log to record time cost of the upper func, with the result that time cost increased almost 1000 times

vllm-0.3.0
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 1.9311904907226562e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 1.9311904907226562e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.1219253540039062e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.1219253540039062e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.09808349609375e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.1219253540039062e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.1219253540039062e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 4.4345855712890625e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.1696090698242188e-05 seconds
INFO 06-03 11:35:10 llm_engine.py:902] detokenize_incrementally cost 2.2649765014648438e-05 seconds

vllm-0.4.2
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.01605677604675293 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.018158912658691406 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.019262075424194336 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.022993803024291992 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.0168459415435791 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.014632225036621094 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.012951850891113281 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.014124870300292969 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.018686532974243164 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.01888108253479004 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.01627206802368164 seconds
INFO 06-03 11:49:34 detokenizer.py:314] detokenize_incrementally cost 0.018700838088989258 seconds

Focus on the fun 'detokenize_incrementally', I find out that len(tokenizer) is introduced to get the vocab size of the tokenizer, while it's not a nice choice because this func costs much more time than tokenizer.vocab_size. I think we should replace all the len(tokenizer) with ````tokenizer.vocab_size``` to improve the generation performance
@DriverSong DriverSong added the bug Something isn't working label Jun 3, 2024
@DriverSong DriverSong mentioned this issue Jun 3, 2024
Merged
@DriverSong
Copy link
Contributor Author

With the changes in pr #5207, the time of generate almost reduce to the same as version 0.3.0

time cost of func detokenize_incrementally
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 1.811981201171875e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 1.7881393432617188e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 1.7642974853515625e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 3.790855407714844e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 2.956390380859375e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 5.555152893066406e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 2.2172927856445312e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 1.7881393432617188e-05 seconds
INFO 06-03 13:54:30 detokenizer.py:311] detokenize_incrementally cost 1.71661376953125e-05 seconds

time cost of generation on qwen1.5-0.5B model with the AdvertiseGen dataset
(RayWorkerWrapper pid=7368) INFO 06-03 13:57:05 custom_all_reduce.py:246] Registering 1715 cuda graph addresses
(RayWorkerWrapper pid=7368) INFO 06-03 13:57:05 model_runner.py:1017] Graph capturing finished in 5 secs.
Processed prompts:   2%|▏         | 24/1070 [00:04<01:23, 12.54it/s]INFO 06-03 13:57:11 metrics.py:334] Avg prompt throughput: 4150.1 tokens/s, Avg generation throughput: 4656.0 tokens/s, Running: 253 reqs, Swapped: 0 reqs, Pending: 789 reqs, GPU KV cache usage: 2.8%, CPU KV cache usage: 0.0%
Processed prompts:  12%|█▏        | 126/1070 [00:09<00:48, 19.55it/s]INFO 06-03 13:57:16 metrics.py:334] Avg prompt throughput: 1470.6 tokens/s, Avg generation throughput: 3535.7 tokens/s, Running: 255 reqs, Swapped: 0 reqs, Pending: 688 reqs, GPU KV cache usage: 3.2%, CPU KV cache usage: 0.0%
Processed prompts:  21%|██▏       | 230/1070 [00:14<00:32, 26.19it/s]INFO 06-03 13:57:21 metrics.py:334] Avg prompt throughput: 1506.8 tokens/s, Avg generation throughput: 3594.8 tokens/s, Running: 252 reqs, Swapped: 0 reqs, Pending: 582 reqs, GPU KV cache usage: 3.2%, CPU KV cache usage: 0.0%
Processed prompts:  31%|███       | 334/1070 [00:19<00:41, 17.70it/s]INFO 06-03 13:57:26 metrics.py:334] Avg prompt throughput: 1585.9 tokens/s, Avg generation throughput: 3439.2 tokens/s, Running: 256 reqs, Swapped: 0 reqs, Pending: 474 reqs, GPU KV cache usage: 3.1%, CPU KV cache usage: 0.0%
Processed prompts:  40%|████      | 430/1070 [00:24<00:46, 13.72it/s]INFO 06-03 13:57:31 metrics.py:334] Avg prompt throughput: 1405.2 tokens/s, Avg generation throughput: 3344.6 tokens/s, Running: 256 reqs, Swapped: 0 reqs, Pending: 379 reqs, GPU KV cache usage: 3.2%, CPU KV cache usage: 0.0%
Processed prompts:  49%|████▉     | 526/1070 [00:29<00:22, 24.51it/s]INFO 06-03 13:57:36 metrics.py:334] Avg prompt throughput: 1358.7 tokens/s, Avg generation throughput: 3423.9 tokens/s, Running: 256 reqs, Swapped: 0 reqs, Pending: 284 reqs, GPU KV cache usage: 3.3%, CPU KV cache usage: 0.0%
Processed prompts:  58%|█████▊    | 624/1070 [00:34<00:22, 19.57it/s]INFO 06-03 13:57:41 metrics.py:334] Avg prompt throughput: 1379.9 tokens/s, Avg generation throughput: 3219.9 tokens/s, Running: 255 reqs, Swapped: 0 reqs, Pending: 185 reqs, GPU KV cache usage: 3.2%, CPU KV cache usage: 0.0%
Processed prompts:  68%|██████▊   | 723/1070 [00:39<00:15, 22.69it/s]INFO 06-03 13:57:46 metrics.py:334] Avg prompt throughput: 1289.4 tokens/s, Avg generation throughput: 3382.1 tokens/s, Running: 256 reqs, Swapped: 0 reqs, Pending: 91 reqs, GPU KV cache usage: 3.2%, CPU KV cache usage: 0.0%
Processed prompts:  76%|███████▌  | 814/1070 [00:44<00:16, 15.71it/s]INFO 06-03 13:57:51 metrics.py:334] Avg prompt throughput: 1341.9 tokens/s, Avg generation throughput: 3227.5 tokens/s, Running: 251 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 3.2%, CPU KV cache usage: 0.0%
Processed prompts:  91%|█████████ | 970/1070 [00:49<00:02, 49.60it/s]INFO 06-03 13:57:56 metrics.py:334] Avg prompt throughput: 0.0 tokens/s, Avg generation throughput: 3975.0 tokens/s, Running: 96 reqs, Swapped: 0 reqs, Pending: 0 reqs, GPU KV cache usage: 1.8%, CPU KV cache usage: 0.0%
Processed prompts: 100%|██████████| 1070/1070 [00:54<00:00, 19.58it/s]
[rank0]:[W CudaIPCTypes.cpp:16] Producer process has been terminated before all shared CUDA tensors released. See Note [Sharing CUDA tensors]

@DriverSong DriverSong mentioned this issue Jun 4, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

[BugFix] Apply get_cached_tokenizer to the tokenizer setter of LLM DriverSong/vllm
1 participant
@DriverSong