[professorpalmer]

One of the five pieces of #285, split per bri-prism's request on #317. Single commit on current prism (eaecb50c7), applies without conflicts. Diagnostics only, off by default; happy to drop it if you would rather not carry it.

What it does

GGML_CUDA_OP_TIMING=1 (with CUDA graphs off, GGML_CUDA_DISABLE_GRAPHS=1): records an event before every graph node on the main stream, charges the time to the next event to that node (a fused group to its first node), aggregates by op / type / shape and prints the top 30 every 100 graphs through the ggml log (INFO level, so -lv 5 in llama-server). Launch gaps inflate the small ops; the large mat-vecs and GEMMs read true.

Why it is useful

It is how the per-op cost of a decode step and of a prefill micro-batch was attributed while tuning the 262k serve, and how a recent prefill regression on this card was traced to a demoted buffer rather than a kernel in a few minutes.

[bri-prism]

Handy tool, and it doesn't change output (greedy is identical with it on or off). A few things would make the numbers trustworthy:

1. Skip no-op nodes (ggml_cuda_is_view_or_noop) when recording events. Right now RESHAPE and VIEW are charged the launch gap to the next kernel, and on a 9B decode RESHAPE is the top line at 8.9%.
2. The per-node cudaEventCreate and the per-graph sync slow decode from about 305 to 76 t/s, so the absolute ms per graph is mostly overhead. An event pool and reading back only at the 100-graph report would fix most of it.
3. The report is GGML_LOG_INFO, so it's only visible with -v. Either log at WARN or document that.
4. The xN column is integer division and shows x0 for nodes that occur in prefill graphs only.

[professorpalmer]

Thank you, all four points are fixed in b587f861f, rebased on prism c96baf4ab:

1. No-op nodes: the event is now recorded after the existing skips (ggml_cuda_is_view_or_noop, nodes computed ahead by a fusion, non-compute nodes), so RESHAPE / VIEW / PERMUTE / TRANSPOSE get no event and no launch gap.
2. Overhead: events come from a pool that is reused, and they are read back once per 100-graph report instead of after every graph. Each record keeps its key as numbers, because the graph's tensors can be gone at report time.
3. Visibility: the report is at WARN now, so llama-server shows it without -v. (llama-bench drops all engine log lines unless it runs with -v, at any level.)
4. xN: the count is the mean per graph with one decimal, so nodes that occur only in prompt graphs show their real fraction instead of x0.

RTX 4070, Bonsai 2 27B PTQ1_0, q4_0 K/V, tg128, CUDA graphs off: 60.9 tok/s without the timer, 45.1 tok/s with it (0.74x; your run of the old version was about 0.25x). The table has no view or no-op lines; the top line is MUL_MAT ptq1_0 5120x17408 cols=1 at 24.8 %.