[Bug] trtllm-bench hangs forever at shutdown when --iteration_log points into a directory that does not exist

Summary

If the parent directory of the path passed to --iteration_log does not exist, the
benchmark runs to completion and then hangs permanently instead of exiting.

The failure mode is costly and hard to diagnose:

• It is deterministic. Every run with such a path hangs.
• It costs the whole run. Generation finishes and the progress bar reaches 100%,
  but stop() never returns, so no report files are written and no statistics are
  printed. Everything the run computed is discarded.
• It produces no diagnostic. The last line logged is Stopping LLM backend..
  The child process that failed does print a FileNotFoundError traceback, but it is
  unrelated in appearance to a hang and nothing in the parent reports the failure.
• It is not interruptible. Ctrl-C does not help; the process is blocked either
  inside a blocking zmq_ctx_term() call or on an await that can never resolve.
  SIGKILL is the only way out.

A single mistyped character in a path is enough to trigger it.

The hang is independent of model, dataset and parallelism, because it happens after
all generation has finished, when the iteration-logging plumbing is the only thing
still running.

Both the throughput and the latency subcommands are affected: both accept
--iteration_log and both drive LlmManager.

Verified on main at commit 3035d47286ef3e232b16430abf376600ef192517; the line
numbers below refer to that commit.

System Info

Not hardware-specific. The defect is in the trtllm-bench iteration-logging plumbing,
and it reproduces with no GPU and no TensorRT-LLM installation using the standalone
script under Reproduction. The commit it was verified on is the one
above; the affected branches and release tags are listed in
Versions affected.

Root cause

Three separate things have to be true, and all three currently are.

1. The writer process binds its socket before it opens the log file

tensorrt_llm/bench/benchmark/utils/processes.py, IterationWriter.run (lines
137-173):

        try:
            # Create a ZeroMQ context and socket for inter-process communication
            logger.debug(f"Iteration logging: Binding to {address}...")
            context = Context(io_threads=1)
            socket = context.socket(PULL)
            socket.bind(address)                      # line 142

            # Open the log file for writing and start listening for messages
            logger.debug(
                f"Iteration logging: Listening for messages on {address}...")
            with open(log_path, "w") as f:            # line 147  <-- raises

open(log_path, "w") at line 147 raises FileNotFoundError when log_path.parent
does not exist. The only handler is except KeyboardInterrupt at line 158, so the
exception propagates, the finally at line 165 tears the socket down, and the child
exits with status 1. Nothing in the parent process ever inspects that exit code.

Note the asymmetry with --report_json, which is handled correctly:
generate_json_report in tensorrt_llm/bench/benchmark/__init__.py does
report_path.parent.mkdir(parents=True, exist_ok=True) at line 185. The
iteration-log path gets no equivalent treatment, so two adjacent reporting options
behave differently for the same user mistake.

The value also passes CLI validation silently. --iteration_log is declared in
tensorrt_llm/bench/benchmark/throughput.py at lines 281-290 as:

@optgroup.option(
    "--iteration_log",
    type=click.Path(dir_okay=False,
                    writable=True,
                    readable=False,
                    path_type=Path,
                    resolve_path=True),
    required=False,
    help="Path where iteration logging is written to.",
)

Because exists defaults to False, click.types.Path.convert returns early from
its except OSError branch as soon as os.stat fails, so the writable=True check
is never reached for a path that does not yet exist. (Confirmed against click 8.3.1;
requirements.txt pins click>=8.3.1,<8.4.)

2. The producer cannot detect that the consumer is gone, and its teardown blocks

tensorrt_llm/bench/benchmark/utils/asynchronous.py, LlmManager.iteration_worker
(lines 320-366):

            context = Context.instance(io_threads=1)       # line 327
            socket = context.socket(PUSH)                  # line 328
            socket.connect(iteration_addr)                 # line 329
            ...
            while not self._stop.is_set():
                async for stats in self.llm.get_stats_async(2):
                    await socket.send_json(stats)          # line 339
                await asyncio.sleep(0)
            ...
            async for stats in self.llm.get_stats_async(2):
                await socket.send_json(stats)              # line 348
        except asyncio.CancelledError:
            logger.debug("Iteration log worker cancelled.")
        except Exception as e:
            raise e
        finally:
            logger.debug("Iteration log worker sending None...")
            socket.send_json({"end": True})                # line 358
            if socket is not None:
                socket.close()                             # line 361
            if context is not None:
                context.term()                             # line 364

socket.connect() on an ipc:// endpoint is asynchronous and does not fail when
nothing is listening, so the producer has no way to notice the dead consumer. libzmq
also creates the outbound pipe optimistically at connect time, which means the socket
is not in the mute state: sends keep succeeding into a queue that will never drain.

That yields two stalls, depending on how many iteration-stats messages the run
produces.

Primary case (fewer than ZMQ_SNDHWM messages): the stall is in context.term()
at line 364. Every send succeeds, the loop exits normally once _stop is set, and
the final drain completes. Then socket.close() at line 361 runs with the default
ZMQ_LINGER of -1, meaning infinite, so zmq_ctx_term() at line 364 waits forever
for the queued, undeliverable messages to flush. This is a blocking C call made on
the event-loop thread, so the entire loop freezes with it.

Secondary case (ZMQ_SNDHWM messages or more): the stall is in the send itself at
line 339. Once the outbound pipe reaches the high-water mark (1000 messages by
default), await socket.send_json(stats) never resolves. Setting _stop cannot help
here, because the task is suspended inside the send rather than at the loop
condition. This is the documented libzmq behaviour once the send high-water mark is
reached: with pyzmq 27.2.0 and libzmq 4.3.5, the default of 1000 lets 1000 sends
complete before the next one stops returning, and SNDHWM set to 3 lets 3 complete.

Either way the user-visible outcome is identical.

3. stop() awaits the iteration-log task with no timeout

tensorrt_llm/bench/benchmark/utils/asynchronous.py lines 368-375:

    async def stop(self) -> None:
        logger.info("Stopping LLM backend.")
        self._stop.set()
        if self._iteration_log_task:
            await self._iteration_log_task     # line 372, unbounded
        assert self._backend_task is not None
        await self._backend_task
        logger.info("LLM Backend stopped.")

stop() is called from async_benchmark's finally at line 504, just after
logger.info("Benchmark complete.") at line 496. Because stop() never returns,
the asyncio.run(...) call at throughput.py line 530 never returns either, so
generate_json_report (lines 555-562) and report_statistics() (line 563) are never
reached.

Recognising it in a log

Warmup calls async_benchmark without iteration_log_addr (throughput.py lines
513-521), so _iteration_log_task stays None and warmup's stop() returns
immediately. Only the measured run passes iteration_writer.full_address
(line 537). With the default --warmup 2, the log therefore ends like this:

... Benchmark complete.
... Stopping LLM backend.

with two Stopping LLM backend. lines over the whole run but only one
LLM Backend stopped.. That mismatch is the quickest way to identify the problem.

Reproduction

Without a GPU

IterationWriter and the producer path can be driven directly. The script below is a
transcription of the current code on main with the LLM replaced by a generator of
placeholder stats dicts. It needs only pyzmq: no model, no GPU, no TensorRT-LLM
installation.

pip install pyzmq
python repro_iteration_log_hang.py 5      # primary case: stalls in context.term()
python repro_iteration_log_hang.py 2000   # secondary case: stalls in send_json()

Output of python repro_iteration_log_hang.py 5, paths elided:

FileNotFoundError: [Errno 2] No such file or directory: '/directory-that-does-not-exist/iteration.log'
IterationWriter child exit code: 1 (non-zero: it died opening the log file)
Benchmark complete.
Stopping LLM backend.

=== still blocked after 30s; thread stacks follow ===
Thread 0x... (most recent call first):
  File ".../zmq/sugar/context.py", line 264 in term
  File "repro_iteration_log_hang.py", line 110 in iteration_worker
  File ".../asyncio/events.py", line 80 in _run
  ...
HANG REPRODUCED

python repro_iteration_log_hang.py 2000 produces the same user-visible outcome,
with the event loop idle in selectors.select because the task is suspended on the
unresolvable await socket.send_json(...).

#!/usr/bin/env python3
"""Standalone reproduction of the trtllm-bench --iteration_log shutdown hang.

Transcribes the two code paths involved, from TensorRT-LLM main:

  * tensorrt_llm/bench/benchmark/utils/processes.py :: IterationWriter.run
  * tensorrt_llm/bench/benchmark/utils/asynchronous.py
        :: LlmManager.iteration_worker  and  LlmManager.stop

The LLM is replaced by a generator of placeholder iteration-stats dicts, so no
model, no GPU and no TensorRT-LLM installation are required. Only pyzmq is
needed. POSIX only: it uses the "fork" start method, as trtllm-bench does.

    pip install pyzmq
    python repro_iteration_log_hang.py 5      # stalls in context.term()
    python repro_iteration_log_hang.py 2000   # stalls in await send_json()

Both print "HANG REPRODUCED" plus the stack of the blocked thread. Exits 0 so
the script is easy to wrap; check the printed verdict, not the exit status.
"""
import asyncio
import faulthandler
import multiprocessing as mp
import os
import sys
import tempfile
import threading
import time
from pathlib import Path

import zmq
import zmq.asyncio

# Any path whose parent directory does not exist will do.
MISSING_PARENT_LOG_PATH = Path("/directory-that-does-not-exist/iteration.log")
WATCHDOG_SECONDS = 30


# --------------------------------------------- processes.py :: IterationWriter
def iteration_writer_run(address, log_path, stop_event):
    """Transcribed from IterationWriter.run, including the latent
    UnboundLocalError in the KeyboardInterrupt branch (a separate defect,
    already addressed by an open PR)."""
    context = None
    socket = None
    try:
        context = zmq.Context(io_threads=1)
        socket = context.socket(zmq.PULL)
        socket.bind(address)                    # bind happens first
        with open(log_path, "w") as f:          # FileNotFoundError raised here
            message = socket.recv_json()
            while not stop_event.is_set() and "end" not in message:
                f.write(f"{message}\n")
                message = socket.recv_json()
    except KeyboardInterrupt:
        while message != b"None":
            message = socket.recv_json()
    finally:
        if socket is not None:
            socket.close()
        if context is not None:
            context.term()


# --------------------------------------------- asynchronous.py :: LlmManager
class PlaceholderLlm:
    """Stands in for LLM.get_stats_async(2)."""

    def __init__(self, n_stats):
        self.remaining = n_stats

    async def get_stats_async(self, _timeout):
        for _ in range(min(50, self.remaining)):
            self.remaining -= 1
            yield {"iter": 0, "cpuMemUsage": 0, "gpuMemUsage": 0}
        await asyncio.sleep(0)


class MinimalLlmManager:

    def __init__(self, llm):
        self.llm = llm
        self._stop = asyncio.Event()
        self.request_seen = asyncio.Event()
        self._iteration_log_task = None

    async def iteration_worker(self, iteration_addr):
        context = None
        socket = None
        try:
            context = zmq.asyncio.Context.instance(io_threads=1)
            socket = context.socket(zmq.PUSH)
            socket.connect(iteration_addr)
            await self.request_seen.wait()
            while not self._stop.is_set():
                async for stats in self.llm.get_stats_async(2):
                    await socket.send_json(stats)   # stalls once SNDHWM is hit
                await asyncio.sleep(0)
            async for stats in self.llm.get_stats_async(2):
                await socket.send_json(stats)
        except asyncio.CancelledError:
            pass
        except Exception as e:
            raise e
        finally:
            socket.send_json({"end": True})
            if socket is not None:
                socket.close()                      # default LINGER is -1
            if context is not None:
                context.term()                      # blocks forever

    async def stop(self):
        print("Stopping LLM backend.", flush=True)
        self._stop.set()
        if self._iteration_log_task:
            await self._iteration_log_task          # no timeout
        print("LLM Backend stopped.", flush=True)

    def run(self, iteration_addr):
        self._iteration_log_task = asyncio.create_task(
            self.iteration_worker(iteration_addr))


# ------------------------------------------------------------------- driver
async def main(n_stats):
    # Transcribed from IterationWriter.__init__.
    socket_path = Path(tempfile.mkstemp()[1])
    address = f"ipc://{socket_path}"

    ctx = mp.get_context("fork")
    stop_event = ctx.Event()
    child = ctx.Process(name="IterationWriter",
                        target=iteration_writer_run,
                        args=(address, MISSING_PARENT_LOG_PATH, stop_event))
    child.start()
    child.join(timeout=10)
    print(f"IterationWriter child exit code: {child.exitcode} "
          f"(non-zero: it died opening the log file)", flush=True)

    backend = MinimalLlmManager(PlaceholderLlm(n_stats))
    backend.run(address)
    backend.request_seen.set()

    # Stands in for the benchmark loop draining every request.
    await asyncio.sleep(3)
    print("Benchmark complete.", flush=True)

    finished = threading.Event()

    def watchdog():
        if not finished.wait(WATCHDOG_SECONDS):
            print(f"\n=== still blocked after {WATCHDOG_SECONDS}s; "
                  f"thread stacks follow ===", flush=True)
            faulthandler.dump_traceback()
            print("\nHANG REPRODUCED", flush=True)
            os._exit(0)

    threading.Thread(target=watchdog, daemon=True).start()

    started = time.monotonic()
    await backend.stop()
    finished.set()
    print(f"stop() returned after {time.monotonic() - started:.2f}s: no hang",
          flush=True)


if __name__ == "__main__":
    asyncio.run(main(int(sys.argv[1]) if len(sys.argv) > 1 else 5))

Through the CLI

printf '%s\n' \
  '{"task_id": 0, "input_ids": [863, 22056, 25603, 11943, 8932], "output_tokens": 32}' \
  '{"task_id": 1, "input_ids": [14480, 13598, 15585, 6591, 1252], "output_tokens": 32}' \
  > /tmp/dataset.jsonl

trtllm-bench --model <model-id> throughput \
  --dataset /tmp/dataset.jsonl \
  --iteration_log /directory-that-does-not-exist/iteration.log

Expected behavior

Either a clear error before the model is loaded, or the directory being created,
matching what --report_json already does.

Actual behavior

The benchmark completes, Stopping LLM backend. is logged, and the process hangs
until killed.

Versions affected

tensorrt_llm/bench/benchmark/utils/processes.py has exactly one commit in its entire
history: 8bb3eea285db15c3b54c66230eb2701505fc863f, "perf: Readd iteration logging for
trtllm-bench" (#3039). Its contents are byte-identical from v0.19.0 through current
main. The bind-before-open ordering has therefore been present since v0.19.0.

The unbounded await self._iteration_log_task in stop() arrived later, in
1ebceb790d482cd3cf386a37efe69a3b18cf75d2 (#5170), which replaced a non-awaited
asyncio.gather(self._iteration_log_task). The earliest tag containing it is
v1.0.0rc6, and the earliest stable release is v1.0.0.

The hang as described is therefore present in every release from v1.0.0 onward,
including the current latest stable release v1.2.1 and the current latest release
candidate v1.3.0rc24. v0.19.0 and v0.20.0 contain the bind-before-open defect
but not the unbounded await.

Existing coverage does not reach this path:
tests/integration/defs/test_e2e.py::test_trtllm_bench_iteration_log builds its log
path with tempfile.mkstemp(dir="/tmp", suffix=".txt"), so the parent directory always
exists.

Suggested fix

Three changes. Each is needed; none is sufficient on its own.

1. processes.py: create the parent and open the file before binding

        try:
            log_path.parent.mkdir(parents=True, exist_ok=True)
            with open(log_path, "w") as f:
                logger.info(f"Iteration logging: Opened log file {log_path}...")
                context = Context(io_threads=1)
                socket = context.socket(PULL)
                socket.bind(address)
                message = socket.recv_json()
                while not stop_event.is_set() and "end" not in message:
                    f.write(f"{message}\n")
                    message = socket.recv_json()
        except KeyboardInterrupt:
            ...   # unchanged
        except OSError as e:
            logger.error(
                f"Iteration logging disabled: cannot write {log_path}: {e}")
            return

The reordering does not introduce a race with the parent's connect(). A PUSH socket
on an ipc:// endpoint that connects before its peer binds queues messages in its
outbound pipe and delivers them once the bind happens. Connecting a producer, sending
a few messages and only then binding the consumer confirms this: every message
arrives.

Validating in capture() in the parent process, before Process.start(), would be
better still, since the user would get the error before the model is loaded rather
than after.

2. asynchronous.py: bound the drain in stop()

    async def stop(self) -> None:
        logger.info("Stopping LLM backend.")
        self._stop.set()
        if self._iteration_log_task:
            try:
                await asyncio.wait_for(self._iteration_log_task,
                                       timeout=ITERATION_LOG_DRAIN_TIMEOUT)
            except asyncio.TimeoutError:
                logger.warning("Iteration log worker did not finish in time; "
                               "the iteration log may be truncated.")

The except is required, not defensive: iteration_worker swallows
asyncio.CancelledError at line 349, so wait_for raises TimeoutError even though
the task then completes.

3. asynchronous.py: make the sends and the teardown non-blocking

                    try:
                        await socket.send_json(stats, flags=zmq.NOBLOCK)
                    except zmq.Again:
                        dropped += 1

and give the PUSH socket a finite linger so context.term() cannot block:

            socket = context.socket(PUSH)
            socket.setsockopt(zmq.LINGER, ITERATION_LOG_LINGER_MS)

Two details are easy to get wrong here.

zmq.NOBLOCK does not raise synchronously on a zmq.asyncio socket. send and
send_json return a Future whose exception is set, so zmq.Again is only observable
if the call is awaited. Writing socket.send_json(stats, flags=zmq.NOBLOCK) without
await swallows the error (and produces a "Future exception was never retrieved"
warning), and a drop counter fed that way would report zero drops forever. The
un-awaited socket.send_json({"end": True}) already at line 358 has the same problem;
it should be awaited, or moved onto a plain synchronous socket.

Bounding the linger is the load-bearing part, not a cosmetic extra. Against the
current code shape with a dead consumer, the three changes combine like this:

A finite linger is preferable to LINGER = 0. Against a dead peer, close() stops
waiting once the configured linger has elapsed, so the shutdown delay is bounded by
whatever value the code sets instead of being unbounded, and a healthy run still gets
to flush its queued tail. LINGER = 0 would silently truncate the end of the
iteration log on successful runs.

The consumer's PULL socket has no outbound queue, so its context.term() at
processes.py line 172 does not block; a linger setting there is harmless but
unnecessary.

Relationship to open PRs

Two open PRs touch these files but not this defect:

• #17731 repairs the
  KeyboardInterrupt drain loop in IterationWriter.run (the message != b"None"
  comparison, which can also raise UnboundLocalError). It does not change the
  bind/open ordering.
• #17735 moves the end-sentinel
  send_json inside the if socket is not None guard in iteration_worker's
  finally. It does not change the blocking send, the linger, or stop().

Both are still open, and both are based on the same file contents as current main.

Happy to open a PR with the three changes above, plus a regression test that points
--iteration_log at a missing directory and asserts the run still reports.

Start with the standalone reproduction, then read IterationWriter.run in tensorrt_llm/bench/benchmark/utils/processes.py and LlmManager.iteration_worker/stop in tensorrt_llm/bench/benchmark/utils/asynchronous.py; trace the measured path through throughput.py. Done means a missing-parent --iteration_log no longer blocks after Benchmark complete, normal reports and statistics are reached, and both throughput and latency paths are covered.