Baseline: Synchronous Blocking via Compute Amplification

============================================================
  vLLM n_completions+logprobs compute amplification
  Finding : finding_01758_199991774 (iteration 1758)
  Server  : http://localhost:8000/
  Model   : Qwen/Qwen2.5-0.5B-Instruct
  Runs    : 10

  Threshold: 46 ms TTFT
============================================================

Trace: 5 concurrent requests sharing prefix_len=32
  r9  : 512-token prompt, max_tokens=64,  n=1, logprobs=None  ← plain victim (+313ms)
  r06 : 512-token prompt, max_tokens=16,  n=8, logprobs=20    ← amplifier  (+578ms)
  r01 : 512-token prompt, max_tokens=16,  n=1, logprobs=20                 (+601ms)
  r03 : 512-token prompt, max_tokens=16,  n=1, logprobs=20                 (+601ms)
  r08 : 512-token prompt, max_tokens=16,  n=1, logprobs=20                 (+602ms)

r06 expands into 8 parallel decode sequences, each computing full-vocab
logprobs every step. All co-scheduled requests pay this cost per step.


  Run  1  (11306ms wall)
    r9      :   9761.9 ms *** SLOW
    r06     :   9519.5 ms *** SLOW
    r01     :   9752.0 ms *** SLOW
    r03     :   9662.5 ms *** SLOW
    r08     :   9838.8 ms *** SLOW

  Run  2  (1263ms wall)
    r9      :     51.2 ms
    r06     :     84.7 ms
    r01     :     87.1 ms
    r03     :     84.5 ms
    r08     :     85.2 ms

  Run  3  (1304ms wall)
    r9      :     45.1 ms
    r06     :    421.0 ms *** SLOW
    r01     :    427.7 ms *** SLOW
    r03     :    427.1 ms *** SLOW
    r08     :    426.7 ms *** SLOW

  Run  4  (1243ms wall)
    r9      :     45.2 ms
    r06     :     77.7 ms
    r01     :    112.9 ms
    r03     :    113.6 ms
    r08     :    110.9 ms

  Run  5  (1257ms wall)
    r9      :     45.5 ms
    r06     :     89.5 ms
    r01     :     85.8 ms
    r03     :     84.8 ms
    r08     :     83.9 ms

  Run  6  (1258ms wall)
    r9      :     47.5 ms
    r06     :     82.6 ms
    r01     :     88.1 ms
    r03     :     87.3 ms
    r08     :     87.1 ms

  Run  7  (1261ms wall)
    r9      :     44.6 ms
    r06     :     77.0 ms
    r01     :     99.4 ms
    r03     :     96.8 ms
    r08     :     97.7 ms

  Run  8  (1248ms wall)
    r9      :     44.1 ms
    r06     :     85.1 ms
    r01     :     91.8 ms
    r03     :     91.0 ms
    r08     :     90.1 ms

  Run  9  (1262ms wall)
    r9      :     54.3 ms
    r06     :     84.4 ms
    r01     :     88.8 ms
    r03     :     88.9 ms
    r08     :     88.0 ms

  Run 10  (1270ms wall)
    r9      :     50.5 ms
    r06     :     92.7 ms
    r01     :     83.2 ms
    r03     :     82.7 ms
    r08     :     82.7 ms

============================================================

  RESULTS SUMMARY
============================================================

  All requests — 50 samples:
    mean :   1070.6 ms
    p99  :   9838.8 ms
    max  :   9838.8 ms
    threshold : 46 ms

  r9 (plain victim, arrived 265ms early) — 10 samples:
    mean :   1019.0 ms
    p99  :   9761.9 ms  (212.2× threshold)

------------------------------------------------------------

  RESULT : CONFIRMED
  p99 TTFT 9838.8 ms exceeds threshold 46 ms (213.9×)

============================================================

Fixed: Compute Isolation via Logprobs Budgeting

r06 expands into 8 parallel decode sequences, each computing full-vocab
logprobs every step. All co-scheduled requests pay this cost per step.

  Run  1  (1534ms wall)
    r9      :     65.2 ms
    r06     :     82.7 ms
    r01     :     89.5 ms
    r03     :    103.8 ms
    r08     :    295.2 ms *** SLOW

  Run  2  (1497ms wall)
    r9      :     48.8 ms
    r06     :     70.0 ms
    r01     :     89.8 ms
    r03     :    107.1 ms
    r08     :    282.9 ms *** SLOW

  Run  3  (1496ms wall)
    r9      :     52.3 ms
    r06     :     83.2 ms
    r01     :     75.3 ms
    r03     :    282.0 ms *** SLOW
    r08     :     94.8 ms

  Run  4  (1503ms wall)
    r9      :     52.7 ms
    r06     :     81.6 ms
    r01     :     86.0 ms
    r03     :    106.6 ms
    r08     :    295.0 ms *** SLOW

  Run  5  (1498ms wall)
    r9      :     55.7 ms
    r06     :     85.6 ms
    r01     :     84.0 ms
    r03     :     98.3 ms
    r08     :    289.8 ms *** SLOW

  Run  6  (1506ms wall)
    r9      :     53.0 ms
    r06     :     79.5 ms
    r01     :    102.9 ms
    r03     :     82.2 ms
    r08     :    291.5 ms *** SLOW

  Run  7  (1505ms wall)
    r9      :     54.0 ms
    r06     :     83.1 ms
    r01     :     82.1 ms
    r03     :    101.7 ms
    r08     :    292.5 ms *** SLOW

  Run  8  (1476ms wall)
    r9      :     49.8 ms
    r06     :     78.0 ms
    r01     :     75.9 ms
    r03     :    280.9 ms *** SLOW
    r08     :     93.5 ms

  Run  9  (1497ms wall)
    r9      :     51.1 ms
    r06     :     71.9 ms
    r01     :     73.7 ms
    r03     :     90.1 ms
    r08     :    279.0 ms *** SLOW

  Run 10  (1504ms wall)
    r9      :     54.8 ms
    r06     :     80.1 ms
    r01     :     84.8 ms
    r03     :    293.8 ms *** SLOW
    r08     :    102.0 ms

============================================================

  RESULTS SUMMARY
============================================================

  All requests — 50 samples:
    mean :    120.8 ms
    p99  :    295.2 ms
    max  :    295.2 ms
    threshold : 46 ms

  r9 (plain victim, arrived 265ms early) — 10 samples:
    mean :     53.7 ms
    p99  :     65.2 ms  (1.4× threshold)

------------------------------------------------------------

  RESULT : CONFIRMED
  p99 TTFT 295.2 ms exceeds threshold 46 ms (6.4×)

============================================================

repo.py
#!/usr/bin/env python3
"""
Minimal reproduction for vLLM n_completions + logprobs per-step compute amplification.
Bug: A single request with n_completions=8 and logprobs=20 expands into 8 parallel
decode sequences each requiring a full-vocabulary logprob computation per step.
Every co-scheduled request in the same decode batch is forced to wait for this
overhead on every step, causing 76-423x TTFT regression for plain requests.
This reproduces finding_01758 (seed 199991774, iteration 1758).
Note: --enable-chunked-prefill does NOT mitigate this — the regression is in the
decode phase, not the prefill scheduling order.
Setup:
    pip install httpx
    python -m vllm.entrypoints.openai.api_server \\
        --model Qwen/Qwen2.5-0.5B-Instruct \\
        --port 8000 \\
        --gpu-memory-utilization 0.95 \\
        --max-model-len 32768 \\
        --enable-prefix-caching \\
        --disable-log-requests
Run:
    python3 repro.py --base-url http://localhost:8000 --runs 10
"""

import argparse
import asyncio
import json
import sys
import time

try:
    import httpx
except ImportError:
    sys.exit("pip install httpx")


def build_prompt(prompt_len: int, prefix_len: int, idx: int) -> str:
    shared = [f"pre{i}" for i in range(min(prefix_len, prompt_len))]
    unique = [f"u{idx}_{i}" for i in range(prompt_len - len(shared))]
    return " ".join(shared + unique)


# ---------------------------------------------------------------------------
# The five requests from finding_01758.
# All share prefix_len=32. Offsets are relative to trace start (seconds).
#
# r06 is the amplifier: n_completions=8 + logprobs=20 expands into 8 parallel
# decode sequences each computing full-vocab logprobs every step.
# r9 is the primary victim: arrives 265ms before the burst, plain request,
# should be nearly done before r06 even arrives.
# ---------------------------------------------------------------------------

REQUESTS = [
    # label     prompt  prefix  max_tok  n_comp  logprobs  temp   stream  offset_s  idx
    ("r9",       512,    32,      64,      1,      None,    None,  True,   0.313,    0),  # plain victim
    ("r06",      512,    32,      16,      8,      20,      1.26,  True,   0.578,    1),  # ← amplifier
    ("r01",      512,    32,      16,      1,      20,      None,  True,   0.601,    2),
    ("r03",      512,    32,      16,      1,      20,      None,  True,   0.601,    3),
    ("r08",      512,    32,      16,      1,      20,      0.5,   True,   0.602,    4),
]

THRESHOLD_MS = 46.0  # expected TTFT for a 512-token prompt on idle server


async def send_request(
    client: httpx.AsyncClient,
    base_url: str,
    model: str,
    label: str,
    prompt: str,
    max_tokens: int,
    n: int,
    logprobs: int | None,
    temperature: float | None,
    stream: bool,
) -> tuple[str, float | None]:
    payload: dict = {
        "model":      model,
        "prompt":     prompt,
        "max_tokens": max_tokens,
        "stream":     stream,
        "n":          n,
    }
    if logprobs is not None:
        payload["logprobs"] = logprobs
    if temperature is not None:
        payload["temperature"] = temperature

    t_send = time.perf_counter()
    ttft   = None

    try:
        if stream:
            async with client.stream(
                "POST", f"{base_url}/v1/completions",
                json=payload, timeout=120.0,
            ) as resp:
                resp.raise_for_status()
                async for line in resp.aiter_lines():
                    if not line.startswith("data: "):
                        continue
                    raw = line[6:]
                    if raw.strip() == "[DONE]":
                        break
                    try:
                        chunk = json.loads(raw)
                        tok   = chunk["choices"][0].get("text", "")
                        if tok and ttft is None:
                            ttft = (time.perf_counter() - t_send) * 1000.0
                    except Exception:
                        pass
        else:
            resp = await client.post(
                f"{base_url}/v1/completions",
                json=payload, timeout=120.0,
            )
            resp.raise_for_status()
    except Exception as exc:
        print(f"  [ERROR] {label}: {exc}", file=sys.stderr)

    return label, ttft


async def run_once(base_url: str, model: str) -> dict[str, float | None]:
    results: dict[str, float | None] = {}
    tasks = []

    async with httpx.AsyncClient() as client:
        trace_start = time.perf_counter()

        for label, plen, pfx, max_tok, n, logprobs, temp, stream, offset, idx in REQUESTS:
            delay = (trace_start + offset) - time.perf_counter()
            if delay > 0:
                await asyncio.sleep(delay)

            task = asyncio.create_task(
                send_request(
                    client, base_url, model, label,
                    build_prompt(plen, pfx, idx),
                    max_tok, n, logprobs, temp, stream,
                )
            )
            tasks.append(task)

        for coro in asyncio.as_completed(tasks):
            label, ttft = await coro
            results[label] = ttft

    return results


async def main() -> None:
    parser = argparse.ArgumentParser(
        description="Reproduce vLLM n_completions+logprobs compute amplification (finding_01758).",
        formatter_class=argparse.ArgumentDefaultsHelpFormatter,
    )
    parser.add_argument("--base-url", default="http://localhost:8000")
    parser.add_argument("--model",    default="Qwen/Qwen2.5-0.5B-Instruct")
    parser.add_argument("--runs",     type=int, default=10)
    parser.add_argument("--settle-s", type=float, default=2.0)
    args = parser.parse_args()

    print("=" * 60)
    print("  vLLM n_completions+logprobs compute amplification")
    print(f"  Finding : finding_01758_199991774 (iteration 1758)")
    print(f"  Server  : {args.base_url}")
    print(f"  Model   : {args.model}")
    print(f"  Runs    : {args.runs}")
    print(f"  Threshold: {THRESHOLD_MS:.0f} ms TTFT")
    print("=" * 60)
    print()
    print("Trace: 5 concurrent requests sharing prefix_len=32")
    print("  r9  : 512-token prompt, max_tokens=64,  n=1, logprobs=None  ← plain victim (+313ms)")
    print("  r06 : 512-token prompt, max_tokens=16,  n=8, logprobs=20    ← amplifier  (+578ms)")
    print("  r01 : 512-token prompt, max_tokens=16,  n=1, logprobs=20                 (+601ms)")
    print("  r03 : 512-token prompt, max_tokens=16,  n=1, logprobs=20                 (+601ms)")
    print("  r08 : 512-token prompt, max_tokens=16,  n=1, logprobs=20                 (+602ms)")
    print()
    print("r06 expands into 8 parallel decode sequences, each computing full-vocab")
    print("logprobs every step. All co-scheduled requests pay this cost per step.")
    print()

    all_ttfts: list[float] = []
    r9_ttfts:  list[float] = []
    run_results = []

    for run_i in range(1, args.runs + 1):
        t0      = time.perf_counter()
        results = await run_once(args.base_url, args.model)
        elapsed = (time.perf_counter() - t0) * 1000.0

        ttfts = [v for v in results.values() if v is not None]
        all_ttfts.extend(ttfts)
        if results.get("r9") is not None:
            r9_ttfts.append(results["r9"])
        run_results.append(results)

        print(f"  Run {run_i:>2}  ({elapsed:.0f}ms wall)")
        for label, *_ in REQUESTS:
            ttft = results.get(label)
            if ttft is not None:
                flag = " *** SLOW" if ttft > THRESHOLD_MS * 3 else ""
                print(f"    {label:<8}: {ttft:>8.1f} ms{flag}")
        print()

        if run_i < args.runs:
            await asyncio.sleep(args.settle_s)

    print("=" * 60)
    print("  RESULTS SUMMARY")
    print("=" * 60)

    if not all_ttfts:
        print("  No TTFT samples collected.")
        return

    all_ttfts.sort()
    mean_ms = sum(all_ttfts) / len(all_ttfts)
    p99_ms  = all_ttfts[int(0.99 * len(all_ttfts))]
    max_ms  = all_ttfts[-1]

    print(f"  All requests — {len(all_ttfts)} samples:")
    print(f"    mean : {mean_ms:>8.1f} ms")
    print(f"    p99  : {p99_ms:>8.1f} ms")
    print(f"    max  : {max_ms:>8.1f} ms")
    print(f"    threshold : {THRESHOLD_MS:.0f} ms")
    print()

    if r9_ttfts:
        r9_ttfts.sort()
        r9_p99  = r9_ttfts[int(0.99 * len(r9_ttfts))]
        r9_mean = sum(r9_ttfts) / len(r9_ttfts)
        print(f"  r9 (plain victim, arrived 265ms early) — {len(r9_ttfts)} samples:")
        print(f"    mean : {r9_mean:>8.1f} ms")
        print(f"    p99  : {r9_p99:>8.1f} ms  ({r9_p99 / THRESHOLD_MS:.1f}× threshold)")
        print()

    print("-" * 60)
    ratio = p99_ms / THRESHOLD_MS
    if p99_ms > THRESHOLD_MS:
        print(f"  RESULT : CONFIRMED")
        print(f"  p99 TTFT {p99_ms:.1f} ms exceeds threshold {THRESHOLD_MS:.0f} ms ({ratio:.1f}×)")
        print()
    else:
        print(f"  RESULT : Damn it! NOT REPRODUCED")
        print(f"  p99 TTFT {p99_ms:.1f} ms is within threshold {THRESHOLD_MS:.0f} ms")
    print("=" * 60)


if __name__ == "__main__":
    asyncio.run(main())