[Bug]: lm-format-enforcer guided decoding kills MQLLMEngine

Your current environment

The output of `python collect_env.py`

(vllm code copied from this PR (@84789334a) was used: https://github.com/vllm-project/vllm/pull/8574) ```text Collecting environment information... PyTorch version: 2.4.0+cu121 Is debug build: False CUDA used to build PyTorch: 12.1 ROCM used to build PyTorch: N/A OS: Red Hat Enterprise Linux 9.4 (Plow) (x86_64) GCC version: (GCC) 11.4.1 20231218 (Red Hat 11.4.1-3) Clang version: Could not collect CMake version: Could not collect Libc version: glibc-2.34 Python version: 3.11.7 (main, Aug 23 2024, 00:00:00) [GCC 11.4.1 20231218 (Red Hat 11.4.1-3)] (64-bit runtime) Python platform: Linux-4.18.0-372.46.1.el8_6.x86_64-x86_64-with-glibc2.34 Is CUDA available: True CUDA runtime version: Could not collect CUDA_MODULE_LOADING set to: LAZY GPU models and configuration: GPU 0: NVIDIA A100-SXM4-80GB GPU 1: NVIDIA A100-SXM4-80GB Nvidia driver version: 535.104.05 cuDNN version: Could not collect 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 Address sizes: 46 bits physical, 57 bits virtual Byte Order: Little Endian CPU(s): 80 On-line CPU(s) list: 0-79 Vendor ID: GenuineIntel Model name: Intel Xeon Processor (Icelake) CPU family: 6 Model: 134 Thread(s) per core: 2 Core(s) per socket: 20 Socket(s): 2 Stepping: 0 BogoMIPS: 5600.05 Flags: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl xtopology cpuid tsc_known_freq pni pclmulqdq vmx ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch cpuid_fault invpcid_single ssbd ibrs ibpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves wbnoinvd arat avx512vbmi umip pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq la57 rdpid fsrm md_clear arch_capabilities Virtualization: VT-x Hypervisor vendor: KVM Virtualization type: full L1d cache: 2.5 MiB (80 instances) L1i cache: 2.5 MiB (80 instances) L2 cache: 160 MiB (40 instances) L3 cache: 32 MiB (2 instances) NUMA node(s): 2 NUMA node0 CPU(s): 0-39 NUMA node1 CPU(s): 40-79 Vulnerability Itlb multihit: Not affected Vulnerability L1tf: Not affected Vulnerability Mds: Not affected Vulnerability Meltdown: Not affected Vulnerability Mmio stale data: Vulnerable: Clear CPU buffers attempted, no microcode; SMT Host state unknown Vulnerability Retbleed: Not affected Vulnerability Spec store bypass: Mitigation; Speculative Store Bypass disabled via prctl Vulnerability Spectre v1: Mitigation; usercopy/swapgs barriers and __user pointer sanitization Vulnerability Spectre v2: Mitigation; Enhanced IBRS, IBPB conditional, RSB filling, PBRSB-eIBRS Not affected Vulnerability Srbds: Not affected Vulnerability Tsx async abort: Not affected Versions of relevant libraries: [pip3] flashinfer==0.1.2+cu121torch2.4 [pip3] numpy==1.26.4 [pip3] nvidia-cublas-cu12==12.1.3.1 [pip3] nvidia-cuda-cupti-cu12==12.1.105 [pip3] nvidia-cuda-nvrtc-cu12==12.1.105 [pip3] nvidia-cuda-runtime-cu12==12.1.105 [pip3] nvidia-cudnn-cu12==9.1.0.70 [pip3] nvidia-cufft-cu12==11.0.2.54 [pip3] nvidia-curand-cu12==10.3.2.106 [pip3] nvidia-cusolver-cu12==11.4.5.107 [pip3] nvidia-cusparse-cu12==12.1.0.106 [pip3] nvidia-ml-py==12.560.30 [pip3] nvidia-nccl-cu12==2.20.5 [pip3] nvidia-nvjitlink-cu12==12.6.68 [pip3] nvidia-nvtx-cu12==12.1.105 [pip3] pyzmq==26.2.0 [pip3] sentence-transformers==3.1.0 [pip3] torch==2.4.0 [pip3] torchvision==0.19.0 [pip3] transformers==4.44.2 [pip3] transformers-stream-generator==0.0.5 [pip3] triton==3.0.0 [conda] Could not collect ROCM Version: Could not collect Neuron SDK Version: N/A vLLM Version: 0.6.1.post2@caa1aa85fe9dc91aff25786a4efacff951aa7a4d vLLM Build Flags: CUDA Archs: Not Set; ROCm: Disabled; Neuron: Disabled GPU Topology: GPU0 GPU1 NIC0 CPU Affinity NUMA Affinity GPU NUMA ID GPU0 X NV12 NODE 0-39 0 N/A GPU1 NV12 X SYS 40-79 1 N/A NIC0 NODE 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_0 ```

Model Input Dumps

No response

🐛 Describe the bug

I was benchmarking the performance of guided decoding using the lm-format-enforcer backend.

Here's the artillery snippet:

config:
  timeout: 100
  target: http://rundemc-dev-service:8000
  phases:
    - duration: 300
      arrivalRate: 1
      name: Load test

  payload:
    # path is relative to the location of the test script
    path: 'payloads.csv'
    fields:
      - prompt
    name: unused

  variables:
    model_id:
      - "mistralai/Mistral-7B-Instruct-v0.2"
    backend:
      - "lm-format-enforcer"

scenarios:
  - name: Test completions
    flow:
      - post:
          url: "/v1/completions"
          json:
            model: "{{ model_id }}"
            prompt: "{{ prompt }}"
            max_tokens: 40
      - post:
          url: "/v1/completions"
          json:
            model: "{{ model_id }}"
            prompt: "{{ prompt }}"
            max_tokens: 40
            guided_decoding_backend: "{{ backend }}"
            guided_choice:
              - "foo"
              - "bar"
              - "baz"
              - "buzz"
      - post:
          url: "/v1/completions"
          json:
            model: "{{ model_id }}"
            prompt: "{{ prompt }}"
            max_tokens: 40
            guided_decoding_backend: "{{ backend }}"
            response_format:
              type: "json_object"
      - post:
          url: "/v1/completions"
          json:
            model: "{{ model_id }}"
            prompt: "{{ prompt }}"
            max_tokens: 40
            guided_decoding_backend: "{{ backend }}"
            guided_json:
              type: "object"
              properties:
                name:
                  type: string
                age:
                  type: integer

Where payloads.csv has some random short texts (<100 input tokens each)

The server eventually crashes due to the health check timing out:

ERROR 09-18 21:04:43 client.py:261] TimeoutError("MQLLMEngine didn't reply within 10000ms")
ERROR 09-18 21:04:43 client.py:261] Traceback (most recent call last):
ERROR 09-18 21:04:43 client.py:261]   File "/workspace/my-vllm/lib64/python3.11/site-packages/vllm/engine/multiprocessing/client.py", line 157, in run_check_health_loop
ERROR 09-18 21:04:43 client.py:261]     await self._await_ack(error_message="Health check failed.",
ERROR 09-18 21:04:43 client.py:261]   File "/workspace/my-vllm/lib64/python3.11/site-packages/vllm/engine/multiprocessing/client.py", line 308, in _await_ack
ERROR 09-18 21:04:43 client.py:261]     raise TimeoutError("MQLLMEngine didn't reply within "
ERROR 09-18 21:04:43 client.py:261] TimeoutError: MQLLMEngine didn't reply within 10000ms
CRITICAL 09-18 21:04:44 launcher.py:99] MQLLMEngine is already dead, terminating server process
INFO:     10.131.3.24:42640 - "POST /v1/completions HTTP/1.1" 500 Internal Server Error
CRITICAL 09-18 21:04:44 launcher.py:99] MQLLMEngine is already dead, terminating server process
INFO:     10.131.3.24:42640 - "POST /v1/completions HTTP/1.1" 500 Internal Server Error
CRITICAL 09-18 21:04:44 launcher.py:99] MQLLMEngine is already dead, terminating server process
INFO:     10.131.3.24:42640 - "POST /v1/completions HTTP/1.1" 500 Internal Server Error
CRITICAL 09-18 21:04:44 launcher.py:99] MQLLMEngine is already dead, terminating server process
INFO:     10.131.3.24:42640 - "POST /v1/completions HTTP/1.1" 500 Internal Server Error
INFO:     Shutting down
INFO:     Waiting for connections to close. (CTRL+C to force quit)

I then added a little print statement to see how long self.engine_step() takes in the MQLLMEngine, and it looks like every now and then a step takes multiple seconds, where it's usually sub-second. Maybe this is because of large amounts of prefill happening? Something is taking quite a long time though and this causes the engine to not be able to respond to a healthcheck since inputs from the client are read serially after each step.

e.g. I see this printing out:

(really long pause here)
         @@@ Engine step took: 9.088980913162231s @@@
         @@@ Engine step took: 0.05881190299987793s @@@
         @@@ Engine step took: 0.12871074676513672s @@@
         @@@ Engine step took: 0.12064170837402344s @@@
         @@@ Engine step took: 0.09240460395812988s @@@

I can dig in more, but it seems not great that it's this easy to knock over the server

Before submitting a new issue...

[X] Make sure you already searched for relevant issues, and asked the chatbot living at the bottom right corner of the documentation page, which can answer lots of frequently asked questions.

vllm-project / vllm