trace: event tracer for the RPC backend, rpc-server and llama-server - #191
trace: event tracer for the RPC backend, rpc-server and llama-server#191danielhanchen wants to merge 8 commits into
Conversation
…ma-server Adds one coherent timing system in place of the ad hoc counters, so the cost of a two node layer split is measured rather than inferred. ggml/include/ggml-trace.h, ggml/src/ggml-trace.cpp JSON line writer, off unless GGML_RPC_TRACE names a file. Call sites read the exported flag directly, so with tracing off the cost is one load and one branch and no clock is read. Also holds the GPU span helper: the timing hooks are resolved through the backend registry, so ggml-base does not link against any GPU runtime. ggml-cuda two entry points exported through the registry: record a CUDA event on the compute stream, and collect the events that have completed. The completions are reported on the host monotonic scale through one anchor event whose completion time was measured once, and nothing ever waits on the GPU. ggml-rpc client: one record per command with the bytes each way, the tensor or graph it belongs to, the thread, the llama-server group, and timestamps at enqueue, first byte sent, last byte sent, our turn in the reply order, first byte of the reply and reply complete. server: one record per command served with receive, execute and reply timestamps, the graph node count and payload size, and CUDA event timestamps around ggml_backend_graph_compute. new RPC_CMD_TRACE_SYNC: a four timestamp exchange at connect time, written into the client trace so the two nodes can be put on one time line. It is only sent while tracing is on. ggml-backend per scheduler split: backend, input count, node count and a GPU span around the submit; the staging path of ggml_backend_tensor_copy broken into host allocation, read back and send, which is the Spark 1 to CPU to Spark 2 cost of the split. llama-server and libllama per group and per iteration: batch build, submit, synchronize, post decode, sampling and result send with slot counts; per llama_decode the scheduler split count. scripts/rpc_trace/merge.py aligns the files with the measured clock offset and emits a Chrome trace with one row per node, thread and group plus a row per GPU, and a per step summary with the idle fraction of each GPU and the biggest idle gap. scripts/rpc_trace/cpu_check.sh two rpc-servers on the CPU backend, run with the trace off and on, output compared.
…erge by time A scheduler runs over several backends and only some of them offer the timing hooks. The probe was cached once for the process, so a split whose first backend was the CPU or the RPC backend disabled the GPU rows for the whole run, and a backend could have been handed to another registry's mark function. The answer is now kept per registry. merge.py walked every event of the file for every phase of every step. The events are indexed by start time and looked up with a bisect instead.
ggml-cuda.cu is also the HIP and MUSA source, and the GPU timing hook uses cudaEventCreate, cudaEventQuery and cudaEventElapsedTime, which the vendor headers did not map yet. Adds the three defines and a single GPU bracket script for the non RPC proof.
…r properly A traced process is normally stopped with a signal at the end of a run, and the tail of the stdio buffer was lost with it. The file is now flushed every 128 lines. The bench script launched the peer server through setsid, so the pid it captured was setsid's and the server, its child, survived every kill. The next cell then found the port taken, logged 'Failed to create server socket' and silently talked to the previous server, which is how a whole set of peer traces came back with nothing but a header. The launch no longer goes through setsid, ssh is given -n, the bind is checked, the port is waited on before and after each cell, and any leftover server on our port is matched with pgrep -x on the binary name and the port in /proc rather than with a pattern that would also match the remote shell.
…, drop the run artifacts The summary named only the single longest stretch of a step in which neither GPU was busy, which is always a prefill batch build and says nothing about the decode steps. It now also reports the total idle time attributed to each host phase, per step. Also removes the bench output and the driver script that were committed by mistake.
…ature/rpc-trace # Conflicts: # tools/server/server-context.cpp
|
Added
It also splits the cell by phase, and that turned out to be the whole answer. Time counts as prefill when any group is inside an iteration that submitted more tokens than it had slots. This has to be a SET of intervals and not a range: a serving cell interleaves prompt batches with decode for its whole length, so "everything before the last prompt iteration" puts most of the decode inside the prefill phase and reports nothing. What it found on a 27B layer split across two DGX Sparks at 128 concurrent rows with two pipeline groups, 313 s window, 557k events, both nodes clock-pinned: Nine tenths of the remaining idle is one device waiting on the other, and two thirds of it lives in the 18 percent of the window that carries a prompt batch. Median idle stretch on the peer is 6.1 ms in decode and 55.2 ms in a prompt iteration. Non-RPC and other-path proof. This commit adds one new file under |
1 participant
What this is
A timing and profiling system for the RPC backend and llama-server, so that the bottlenecks of a
two node layer split are measured rather than inferred. It replaces the ad hoc pieces used so far
(RPC command counters in the client, per group timers in the server) with one tracer that both
nodes write to and one tool that merges them.
Based on
feature/pipeline-groups.Design
ggml/include/ggml-trace.handggml/src/ggml-trace.cpplive in ggml-base, so every binary thattakes part (libllama, llama-server, the RPC backend, ggml-rpc-server) can raise events without a
new dependency.
Off by default, and free when off. The tracer writes nothing unless
GGML_RPC_TRACE=<path>is set, or
ggml-rpc-server --trace <path>. Call sites read the exported flag directly:so with tracing off the cost is one load and one branch; no clock is read, nothing is formatted
and no allocation happens. There is no change to any output byte with the tracer off or on.
JSON lines. One header object per file, then one object per event, one file per process.
A line is built in the calling thread and handed to the file under a mutex, and the file is
flushed every 128 lines so that a process stopped with a signal does not lose its tail.
Clock alignment. A new
RPC_CMD_TRACE_SYNCcarries a four timestamp exchange (client sendsat t1, peer stamps t2 on receive and t3 on reply, client stamps t4), done once per connection at
connect time and only while tracing is on; the peer always answers it. The resulting offset is
written into the client trace, and the merge tool uses it to put both nodes on one time line.
Measured offsets on the pair were about 1.8 s between the two boot clocks, with round trips in
the tens of microseconds.
What is recorded
RPC client, one record per command: command type, bytes sent and received, the tensor name or
graph uid it belongs to, the calling thread, the llama-server pipeline group (threads tag
themselves through a thread local), and timestamps at enqueue into the dispatcher, first byte
sent, last byte sent, our turn in the reply order, first byte of the reply, reply complete.
Scheduler, per split: the backend, the input count and the node count; and the staging path of
ggml_backend_tensor_copybroken into host allocation, read back and send. That is theSpark 1 to CPU to Spark 2 hop of a layer split, visible as its own span.
rpc-server, one record per command served: receive start and end, execute start and end, reply
start and end, bytes each way, graph node count and device.
GPU. A backend submit only queues the work, so host timestamps around it say nothing about
when the kernels ran. The CUDA backend exports two entry points through the registry
(
ggml_backend_cuda_trace_mark,ggml_backend_cuda_trace_poll), so ggml-base and the RPC backenddo not have to link against CUDA. They record CUDA events on the compute stream around
ggml_backend_graph_computeand report the completions on the host monotonic microsecond scale,anchored by one event whose completion time on the host was measured once. Nothing ever waits on
the GPU: the completed spans are collected from points where the caller is idle anyway (the serve
loop between commands, the scheduler synchronize). The hooks are looked up per backend registry,
so a scheduler that runs over a CPU or RPC backend as well still gets the CUDA rows.
llama-server, per group and per iteration: batch build, submit (
llama_decode),llama_synchronize, post decode, sampling and result send, with slot counts. libllama, perllama_decode: the scheduler split count, with the per split backend coming from the schedulerevents above.
Tools
scripts/rpc_trace/merge.pyreads the files of both nodes, aligns them with the measured clockoffset and writes
chrome://tracing, or the Perfetto UI) with one row per node, thread andpipeline group, the phases of each RPC command as nested slices, and one row per GPU carrying
the CUDA event timings, and
the idle fraction of each GPU, the longest stretch of the step in which neither GPU was busy,
and the total idle time attributed to each host phase.
scripts/rpc_trace/cpu_check.shis the CPU validation: two rpc-servers on the CPU backend and onellama-server splitting layers over them, run once with the trace off and once with it on, with the
generated text compared.
scripts/rpc_trace/gpu_trace.shandscripts/rpc_trace/nonrpc_bracket.shrun the cells below.
Overhead
Measured, not assumed: every configuration was run with the tracer off and on.
Layer split over two nodes, Qwen3.8-27B UD-Q4_K_XL, 32 concurrent, npp 128 / ntg 256,
--cache-ram 0,-c 16384, whole cell tok/s:--device CUDA0,RPC0--device RPC0,CUDA0--device RPC0,CUDA0That is +0.3, -1.2 and +1.9 percent, in both directions, so within run to run noise. The client
writes about 865 events per second (19 MB over a 170 s cell) and the peer about 60 per second.
Non-RPC and non-CUDA workloads
The tracer lives in ggml-base and adds two entry points to the CUDA backend's registry, so it is
on the path of workloads that never touch RPC. It costs them nothing.
Single GPU, no
--rpc,llama-batched-bench -c 32768 -npp 512 -ntg 128 -npl 1,8,32on the samemodel, run base / new / base / new-with-the-trace-on, prompt and generation tok/s:
The node dropped to a lower clock state between the second and the third pass (prompt throughput
falls from about 828 to about 679 for both builds), so the comparisons that hold are the ones
inside one clock state: new against base at npl 1 and 8 is -0.2 and -0.3 percent on prompt, new
against the base repeat at npl 32 is -0.2 percent on prompt and +0.8 on generation, and new with
the trace on against the base repeat is -0.3 and -0.2 percent. Nothing outside noise.
Bit exactness, five greedy prompts, 48 tokens each:
74926c4ef135f3cc89ad20cd5ec7e445for the base, for this branch withthe trace off, and for this branch with the trace on;
-DGGML_CUDA=OFF -DGGML_RPC=OFF: md5177dc61e0703eba3bdaf7bf1131f0458forthe same three.
Build configurations checked:
-DGGML_RPC=OFF -DGGML_CUDA=ONand-DGGML_CUDA=OFF -DGGML_RPC=OFFboth build clean, and the CPU only build still produces a usable trace of thellama and scheduler events with no GPU rows.
Other backends. Vulkan has no
get_proc_addressat all and the registry returns NULL for thatcase; Metal and SYCL fall through to NULL for a name they do not know.
ggml_trace_gpu_begintherefore gets no hook, returns 0 and records nothing, and no other line of those backends is
touched.
ggml-cuda.cuis also the HIP and MUSA source, and the vendor headers did not mapcudaEventCreate,cudaEventQueryorcudaEventElapsedTime, so those two builds would not havecompiled; the three defines are added.
The three timelines
Per decode step, in milliseconds, from the traces.
localGPUandpeerGPUcome from CUDA eventson the compute stream of each node, so they are what the GPUs did, not what the host queued.
idle bothis the part of the step in which neither GPU was busy.GPU busy over the whole cell, and RPC bytes per step:
What the traces say.
logits of 32 rows over a 248320 token vocabulary.
llama_decodedoes not return until thewhole step is finished (submit 303 ms, synchronize 0), because the blocking GET_TENSOR of the
logits sits inside it. The two GPUs never overlap: 150.0 and 149.7 ms of GPU work inside a
325.6 ms step, each of them idle through the other's stage. Named bottleneck: the serial chain
itself, with the logits return as the transport cost that pays for nothing.
back, and the step now splits into submit 159 ms and synchronize 130 ms. The step barely moves
(312.3 against 325.6) because the stages still alternate: 140.0 and 154.9 ms of GPU work in a
312.3 ms step. Named bottleneck: still the serial chain. The staged copy of the hidden state
through a host buffer (
ggml_backend_tensor_copy, since the RPC backend has nocpy_tensor_async) is 148.4 ms per step here, which is the span an asynchronous device todevice path would attack; that number includes the blocking wait for the peer's graph, so it is
an upper bound on the copy itself.
step, both GPUs at 88 to 90 percent, and only 5.9 to 6.6 ms per step in which neither GPU is
busy against 24 to 27 ms with one context. Named bottleneck: GPU compute. The host path is off
the critical path because one group runs it under the other group's GPU work.
(sampling and streaming) and batch build 8.3 to 9.5 ms; with two groups, batch build 2.6 to
3.3 ms and post decode 0.1 to 0.3 ms. The single longest idle gap in every cell is a prefill
step's batch build, 0.9 to 1.3 s, which is a time to first token cost and not a decode cost.
Validation
CPU harness (
scripts/rpc_trace/cpu_check.sh, two local CPU rpc-servers, three greedy prompts):the generated text is byte identical with the trace off and on, the trace files parse, and the
measured clock offsets between the local processes are 0 and 1 us with a 14 to 16 us round trip.