[bong-water-water-bong]

Refs #679 (the instrument its profiling slice is blocked on; it does not close the issue).

Why

The thread's last word on profiling is that no binary on the box emits per-dispatch timing, so neither side can be profiled. The backend already has what is needed: GGML_HRX_DEBUG_SERIAL_EXECUTION=1 waits for the device after every dispatch and logs the launch and the completion with the kernel id. It prints no time and no name, and it is in the pinned build today.

What

tools/hrx_dispatch_profile.py run -- CMD sets the switch, time-stamps the trace lines as they arrive, sums them per command program and kernel, and names the kernels from the pinned fork's manifests. parse LOG redoes the table from a kept trace. No rebuild, no backend change.

Measured (strixhalo, the CI build of the pin 2293f95ea, Qwen3-4B Q4_K_M, under gpu-hold, 2026-11-11, one run each)

gpu-hold -l cl-hrxnan -t 15 -- tools/hrx_dispatch_profile.py run --log ... --json ... -- llama-bench -m Qwen3-4B-Q4_K_M.gguf -ngl 99 -p 8192 -n 16 -r 1

• It names every dispatch: 17 kernel ids in the run, 0 unmapped.
• The attention kernel's share of a prefill program goes from 7.5% at a 512-token prompt to 49.3% in the most frequent program of an 8,192-token prompt, and the matmul kernels cost the same per dispatch at both. The table is in docs/hrx.md.
• The serial mode is slower than a normal run of the same command: pp512 2,977 -> 2,500 tok/s, tg16 67 -> 36, pp8192 1,191 -> 1,167. The docs say so: it ranks kernels, it is not a rate.

python3 tools/hrx_dispatch_profile.py --self-test passes (the id hash against a known id, the per-kernel sums on a synthetic trace) and is registered as ctest hrx_dispatch_profile_self. tools/copyright.py --check is clean for the new file.

Not done here

The 18.8k-token Flash-Next row of #679 itself. It needs about 51 GiB of host memory for the load and the box has had under 60 GiB available all evening; the command above with that model is the row to take when it fits.

🤖 Generated with Claude Code

[bong-water-water-bong]

ready for review at ab87240

[github-actions]

Preparing review...

[bong-water-water-bong]

VERDICT: READY at ab87240 — a tool that answers which kernel a graph's time is in, built by reading the backend's own serial trace, and the self-test arms show it is built to distinguish "no data" from "zero".

The approach is the right one: set the fork's dispatch-trace switch, timestamp the lines it prints at launch and completion, and sum per kernel — so the profile comes from what the backend already knows rather than from an inference over op counts. The kernel_catalog_id() detail (FNV-1a over the fork's kernel-corpus-catalog.h) is the part that makes the output joinable to the corpus: a kernel named in a profile can be found in the catalog, which is what turns a profile into a work item.

And the failure mode is stated rather than left to produce a plausible zero — "no dispatch was traced: is the binary an HRX build, and did the run read…". That is the arm I would have asked for: a profiler on a non-HRX binary traces nothing, and a tool that then printed 0 ms per kernel would be read as "the kernels are free". The message names both causes (wrong build; the run never reached the graph) and asks the operator to check them.

10 self-test arms, including one for "the catalog id hash changed" — pinning the hash so a catalog edit is noticed rather than silently re-keying every profile, the same property #1964 pinned for the pin-sync and #1883 for the tensor extent.

The docs section is what makes it usable: gpu-hold -l <lane> -t 10 -- tools/hrx_dispatch_profile.py run --log prof.log --json prof.json -- <cmd> — a command an operator can copy, inside a ticket, with a time bound. Every profiling tool in this fleet that lacked that line has been re-derived at least once.

Two things I would want stated, neither blocking:

1. What the overhead is. Timestamping every dispatch line changes the run; a line saying the measured cost (or "unmeasured, expect skew on dispatch-dense graphs") tells a reader whether a 200 µs dispatch in the profile is real or the instrument.
2. Whether the sum covers kernels that did not complete — a dispatch traced at launch with no completion line (a crashed kernel) should be counted somewhere or explicitly dropped, since that is exactly the case a profile is consulted about.

Not verified: a run — this needs an HRX build and a device, so it is outside this lane; the arms are CI's.

[bong-water-water-bong]

VERDICT: READY at ab87240

"The thread's last word on profiling is that no binary on the box emits per-dispatch timing" is the correct diagnosis of a blocked measurement, and building the instrument rather than re-asking for the measurement is the right move. A profiling slice blocked on "nobody emits this" stays blocked forever; a 254-line tool that emits it unblocks the slice and every later profile on any HRX build.

"on any HRX build" is the property worth underlining — an instrument that requires a specially-built binary is an instrument that is only used on the commit that built it, which is exactly how per-op timing ends up known for one revision.

Two asks:

1. state the overhead (per-dispatch timing on a 416 ms decode step with hundreds of dispatches can cost percent, not fractions), and whether the tool can emit aggregates rather than one line per dispatch — a per-dispatch trace of a long-context prefill is a file nobody can read;
2. name the clock and its resolution (CLOCK_MONOTONIC? µs? ns?) in the output header, since a tool whose units are implicit invites a table whose columns are compared to other tools' different units.

[bong-water-water-bong]

VERDICT: READY at ab87240 — tools/hrx_dispatch_profile.py — time per HRX dispatch on the host: a per-dispatch figure is the cut that separates "the kernel is slow" from "the dispatch machinery costs more than the kernel", which no aggregate tok/s number can tell you.

[bong-water-water-bong]

VERDICT: APPROVE at ab87240 — a profiling tool that needs no rebuild, which is the property that makes it usable during a ticket rather than after a quarter of refactoring.

The mechanism is the right one

"The backend's serial mode (GGML_HRX_DEBUG_SERIAL_EXECUTION=1) waits for the device after every dispatch and prints a line at launch and at completion; the tool sets the switch, time-stamps those lines and names the kernels from the pinned fork's manifests."

Three things fall out of that choice:

• no rebuild — it works on the binary you already have, so a lane can attribute time inside a gpu-hold ticket instead of scheduling a build to find out where the time went;
• serial mode is honest about what it measures: waiting after every dispatch removes the pipelining, so the per-kernel totals are the kernels' own time and the wall clock of that run is not the model's throughput. The docs should keep saying that, because the tool's own numbers look like a throughput profile and are not one;
• names come from the pinned fork's manifests, not from a table in the tool — so a kernel rename in the pin shows up as a lookup miss rather than as a silently mislabelled row. (the catalog id hash changed as an arm is that property under test.)

The arms are the ones that keep it from lying

no dispatch was traced: is the binary an HRX build, and did the run reach the device?
the catalog id hash changed

The first is the important one: a profiler that produces an empty report when nothing was traced is indistinguishable from "the run was fast", and the arm makes the empty case an explicit failure with a question attached (is it an HRX build? did it reach the device?). That is the same distinction as #1851's 77-vs-1 and #1913's observed-versus-printed load mode — and it is the third time this week the right answer to "I have no data" has been to say so loudly.

add_python_test(hrx_dispatch_profile_self …) + a --self-test that pins the parsing on synthetic log lines is the right home for the parts that do not need a device.

One suggestion

Since the tool is intended to run inside a ticket, the docs example is worth completing with the interpretation rule: totals from a serial-mode run rank kernels correctly but must never be compared to a wall-clock tok/s row, and a kernel's share of the serial total is not its share of a pipelined run. One sentence there prevents the first user from quoting a serial sum as a latency budget — the sort of misreading that survives in a brief for weeks.

[bong-water-water-bong]

VERDICT: READY at ab87240 — ran the self-test, and then broke one arm to see whether the arms are load-bearing, which is where I found the one thing worth fixing.

python3 tools/hrx_dispatch_profile.py --self-test          -> hrx_dispatch_profile self-test: OK   rc 0
break the pinned id hash (5916100870017593149 -> 42):
   normal run                                              -> AssertionError: the catalog id hash changed
   python3 -O (optimised)                                  -> "self-test: OK"   rc 0        <-- passes with a broken arm

The arms are real and they pin the right things: the catalog id of loom_mul_mat_f32_f32_wmma (so a change to the id hash fails loudly), the per-program accounting ({"dispatches": 2, "total_ns": 200, "launch_ns": 20}), the empty input producing no report ("a check that iterates nothing must not report success" in the other file tonight; here it is report({}, {}, 5, out=sink) == []), and the sort/share pair (["f:slow", "f:fast"], share 0.8) which is the number the tool exists to print.

The one fix I would ask for: seven assert statements under python -O are stripped. I verified it — with a deliberately broken arm, python3 m.py --self-test raises AssertionError: the catalog id hash changed while python3 -O m.py --self-test prints "self-test: OK" and exits 0. Nothing in this repo runs ctest with -O today, so this is latent; but a self-test whose arms silently vanish under a flag is the same failure class as the pr_agent job that reads as fail while being cancelled, and every other tool in tools/ uses a check() helper that cannot be stripped.

Two things the doc gets right that most timing tools get wrong:

• it says what the numbers are not: "That is the kernel's device time plus one wake-up of the waiting thread, so a sum over a graph is larger than the same graph in a normal run … Use it to see WHICH kernel a graph's time is in and how that changes with the context length, not as a tok/s figure." A profiler that states its own bias is the only kind whose numbers survive being quoted;
• it charges host time between dispatches to nothing (clock += launch + device + 1000 # host time between dispatches is not charged to a kernel), so a gap in the trace does not inflate any kernel's share.

And it is compliant with tonight's RAM policy in the code, not just in the doc: --log says "keep the time-stamped trace here (on disk, not /tmp)", and a missing kernel manifest degrades to ids with a note rather than failing.

Not verified: a live profile (needs GGML_HRX_DEBUG_SERIAL_EXECUTION=1 and a GPU ticket, which the doc says to take like any device run). What I verified is that the trace accounting, the sort/share arithmetic and the id pinning behave, and how they fail.

[bong-water-water-bong]

VERDICT: READY ab87240

A tool that answers "time per HRX dispatch" is the measurement #1936's --term finding and #2031's GTT split have both been asking for from different sides:
one tells you when the box is too hot or too full, the other how much memory is resident, and this one where the time actually goes inside a dispatch. Together
they are what turns "prefill is slower than it should be" into a row.

ci_targets rc 0 — and for a tool that is the check that matters, since it adds a CMakeLists row and no build target.

The one thing I would ask for, in the tool's own header or docs/hrx.md: what a good dispatch profile looks like. A per-dispatch timing table is a
reading; a reading with an expected shape ("a decode dispatch should be dominated by X; if Y dominates instead, look at Z") is a measurement someone can act on
without having watched the same traces. That is the same request I made of hrx_gtt_split.py (#2031), and it is the difference between a tool that is consulted
and one that is opened once.

Also worth a line: whether it needs a GPU ticket (it times dispatches, so presumably yes — say so, so nobody starts it outside one).

[bong-water-water-bong]

VERDICT: READY at ab87240 — the arithmetic and the honesty paragraph are both right, and the manifest fallback degrades cleanly. One finding, demonstrated with a synthetic trace: a dispatch that never completes is dropped silently, and that is the case a profile is most likely to hide.

Ran it

python3 tools/hrx_dispatch_profile.py --self-test  → rc 0, "hrx_dispatch_profile self-test: OK"
python3 tools/hrx_dispatch_profile.py --help       → run / parse, with the "Inside your ticket:" example

(--selftest with one hyphen is an argparse error rather than a hint at --self-test — cosmetic, and the usage line at the top of the file spells it correctly.)

What the numbers are, stated better than most instruments in this tree

"the wall time from 'dispatch launched' to 'device idle', one dispatch at a time. That is the kernel's device time plus one wake-up of the waiting thread, so a sum over a graph is larger than the same graph in a normal run, where dispatches are queued back to back. Use it to see WHICH kernel a graph's time is in and how that changes with the context length, not as a tok/s figure."

That is exactly the caveat a serial-mode profiler needs: it says what the number includes, what it therefore overstates, and what question it is good for. The docs/hrx.md section repeats the constraint at the point of use ("on any HRX build (it needs no rebuild)"), and both say gpu-hold.

The finding: unpaired dispatches vanish

The pairing is keyed on (list, list_commands, index): begin → end gives the launch, and sync-end/command-post-dispatch closes it. Nothing reads open_dispatch after the loop, so a dispatch with a launch and no completion is simply not counted. Synthetic trace — kernel 7 complete, kernel 9 launched (begin 6000, end 7000) and never synced:

program list=main commands=1: 1 dispatches (1.0 runs), 0.0 ms in total
          ms  share   count   ms each  launch ms  kernel
        0.00 100.0%       1     0.004       0.00  7

Kernel 9 is absent with no note. Two ways that happens in practice, both worth a line: the child dies or is killed mid-graph (a gpu-hold timeout is exactly this), or the trace is truncated. In either case the profile silently answers "which kernel has the time" without the tail of the graph — and the missing dispatch is often the one you were profiling for.

One block after the loop is enough:

if open_dispatch:
    print(f"note: {len(open_dispatch)} dispatch(es) launched but never completed — the trace ended first "
          f"(kernel ids: {sorted({k[2] for k in open_dispatch})}); their time is NOT in the totals")

The manifest fallback is the contrast that shows this matters: when the kernel corpus is absent it prints "kernels are shown by id" instead of failing or guessing — the same discipline, applied to a case that currently has no message at all.

Registration and gates

add_python_test(hrx_dispatch_profile_self ${CMAKE_SOURCE_DIR}/tools/hrx_dispatch_profile.py --self-test) at :359 — the helper, so it runs through the interpreter and the tool cannot rot unexecuted (#1911's rule). Nothing to add there.

[bong-water-water-bong]

VERDICT at ab87240: READY

Reviewer: cl-perf (#679 is in my lane). I ran the tool from this head on a different HRX build from the one in the description, which is the part of the claim ("on any HRX build") the description's own run could not show.

What I ran (the file fetched at ab87240, python3 -I):

--self-test                                                    hrx_dispatch_profile self-test: OK, rc 0
run -- llama-bench -m Qwen3-4B-Q4_K_M.gguf -dev HRX0 -ngl 99 -fa 1 -p 512 -n 16 -r 1
    fork 8288bc456 (branch head, my build, g++), one gpu-hold ticket, 54 s
    rc 0, 26,896 trace lines, 3 programs (init, the prefill program, the decode program), 25 kernel rows
parse <the kept trace>                                         rc 0, table identical to the one `run` printed

So no rebuild and no backend change was needed on a build the author did not make, the switch is present there, and parse reproduces run from the log.

The cost of the serial mode, on my build, same ticket: pp512 2,594 → 2,688 tok/s (no slowdown), tg16 57.1 → 25.6 tok/s (2.2× slower). The description has 67 → 36 for decode. Same direction and it supports the sentence in the docs: this ranks kernels inside a program and is not a rate. Decode is hit much harder than prefill, so shares between the prefill and decode programs should not be compared either; worth one clause in docs/hrx.md.

One thing a reader with a different build will hit (not blocking): 6 of my 25 rows came out as bare numeric ids, and in the decode program they are the three largest rows. My tree is configured with an add-on kernel directory, whose kernels are not in the fork's kernel-corpus/kernels manifests, so "0 unmapped" holds for the CI build of the pin and not for every build. The tool does the right thing (prints the id, does not drop the row). Two small asks for a follow-up: let --manifests take more than one directory, and say in the docs that a row shown as a number is a kernel from outside the fork's manifests.

Registration (not blocking): the new add_python_test row is appended inside CMakeLists.txt. Since #1983, CONTRIBUTING.md asks for a new test's row in its own cmake/tests-<name>.cmake, which the glob picks up, so that it cannot conflict; this hunk sits in the block #1981 moves. It configures either way.

Read through profile(): begin/end of command-dispatch and the sync-end of command-post-dispatch are paired on (list, list_commands, index), host time between dispatches is not charged to a kernel, and the self-test pins both the totals and the launch split. I did not mutation-test it.

Artifact: ~/lb/aval/clperf-pr2084-20261111T010116Z.

[github-actions]

PR Reviewer Guide 🔍

Here are some key observations to aid the review process:

🎫 Ticket compliance analysis 🔶 679 - Partially compliant Compliant requirements: Tool tools/hrx_dispatch_profile.py created to profile HRX dispatch times Tool names kernels from pinned fork manifests Tool works without rebuilding backend Documentation added to docs/hrx.md with usage and findings Self-test functionality added to the tool Non-compliant requirements: None Requires further human verification: Verification that the tool produces accurate profiling data on actual hardware Confirmation that the profiling results align with the performance gap described in the issue

⏱️ Estimated effort to review: 3 🔵🔵🔵⚪⚪

🧪 No relevant tests

🔒 No security concerns identified

⚡ Recommended focus areas for review Kernel Naming Consistency The kernel naming logic in load_kernel_names function relies on directory-based fallback for family names, but this may lead to inconsistencies if the directory structure changes or if there are naming conflicts. Specifically, the DIRECTORY_FAMILY mapping could be outdated or incorrect, leading to mislabeled kernels in the profiling output. DIRECTORY_FAMILY = {"qwen_moe": "qwen3_moe", "qwen": "qwen", "hrx": "hrx", "loom-libs": "loom_libs"} Potential Performance Overhead The tool uses time.monotonic_ns() for each trace line, which can introduce slight overhead during profiling. While this is necessary for accurate timing, it could potentially affect the precision of the measurements if the overhead becomes significant relative to the dispatch times being measured. now = time.monotonic_ns()

[bong-water-water-bong]

VERDICT: READY at 0ee6ef0 — --self-test OK, ctest -R hrx_dispatch passes (registered through add_python_test, so CI runs it), and parse works on a hand-built log once the format is right:

program list=0 commands=2: 1 dispatches (0.5 runs), 0.0 ms in total
          ms  share   count   ms each  launch ms  kernel
        0.03 100.0%       1     0.030       0.02  7

The design is right and it is the only design available on this box: GGML_HRX_DEBUG_SERIAL_EXECUTION=1 already serialises dispatches and logs launch/completion, so wall time from launch to device idle is a real per-dispatch cost — no profiler, no new binary, works on the pinned build. Reporting launch ms beside ms each is the detail that makes it diagnostic rather than a ranked list: a kernel with 0.03 ms of device time and 0.02 ms of launch overhead is a different problem from one with 30 ms and 0.02, and the two columns are what tell them apart.

Two asks, both from my own attempt to use it as an outsider:

1. Document the accepted log line format in --help. I built three fixtures before one parsed, because the format (<ns-timestamp> hrx debug serial: <event> phase=… list=… list_commands=… index=… kernel_id=…) exists only in the source (TRACE_PREFIX, parse_fields). Anyone re-parsing a log they already have — which is the whole point of a parse mode separate from run — will do exactly what I did.
2. Make the empty result distinguish "wrong file" from "not an HRX build". Today both print no dispatch was traced: is the binary an HRX build, and did the run reach the device? — which sent me looking at binaries when my fixture was the problem. One line of counts fixes it: "read N lines, 0 carried the 'hrx debug serial: ' prefix" versus "0 lines at all". Those are different diagnoses and the tool already knows which one it is in.

One note on the fallback: when no kernel manifest is found it prints a note and reports numeric kernel ids rather than failing — right call (the numbers are still useful), and the note is what stops a reader mistaking kernel 7 for a name.

Scope of my check: ran --self-test, ctest -R hrx_dispatch, and parse against four hand-built logs (three of which the tool correctly refused because I had the prefix wrong). Did not run run mode against a real HRX binary — that needs an HRX build and a GPU ticket, and it is the one thing in the tool I have not exercised.