feat(benchmark): per-node cost and bottleneck attribution for a run
--benchmark <path> reports cumulative CPU and wall time per node and names the node pacing the run. The pacing node is located from sampled channel occupancy, not from time-in-node: backpressure inflates time-in-node for everything downstream of the real bottleneck, so the obvious measure names the victim rather than the cause. Sampling starts with the network and stops before it is destroyed. Channel fill is instantaneous and everything has drained by shutdown, so a single read at the end reports an idle pipeline however congested it was. kill -USR1 dumps the table from a running or wedged process. Channel occupancy identifies a stalled node -- full input, empty output -- without a debug build or a debugger, which is the difference between diagnosing the AR-004 hang in seconds and reproducing it under gdb. Two knobs this exposes for measurement rather than sets: SAE_CV_THREADS, because OpenCV's TBB arena and KPN's thread-per-node are two schedulers unaware of each other on the same cores; and SAE_CUDA_BLOCKING_SYNC, because the default spin-wait held the embedder thread at 99.7% user time while nvidia-powerd cut the GPU's clock from 1005 to 210 MHz. Neither default changes until a measurement says it should. TRACES: VR-015 | PR-004
This commit is contained in:
+161
-3
@@ -124,11 +124,169 @@ bleeding across a boundary may be the join rather than a tracking fault.
|
||||
|
||||
| Path | Realtime factor | Sampled fps | 17-min film |
|
||||
|---|---|---|---|
|
||||
| `build/` (TensorRT) | **2.0×** | ~10 | ~8 min |
|
||||
| `build/` (TensorRT) | **8.25×** | 41.3 | **2.1 min** |
|
||||
| `build-ort/` (ORT) | 0.54× | 2.7 | ~32 min |
|
||||
|
||||
Throughput varies strongly with face density; a sparse stretch measured 8×
|
||||
realtime, so quote the whole-film average, not a window.
|
||||
TensorRT figure re-measured 2026-08-04 over the whole film at `--fps 5
|
||||
--min-face-px 32 --expand-gallery`: 5129 frames, 1025.4 s of film in 124.2 s
|
||||
wall. Two runs agreed to 0.4% (124.2 s clean, 124.7 s under gdb). It supersedes
|
||||
an earlier 2.0×; that figure predates the current tree and was not re-derived
|
||||
here, so treat the gain as measured rather than explained.
|
||||
|
||||
Throughput varies strongly with face density, and **a short window is not a
|
||||
sample of the film**. The opening 60 s benchmarks at 23.9× — decode there costs
|
||||
4-6 ms/frame against a 12.35 ms whole-film mean (n=510), because seeking forward
|
||||
in VP8/WebM gets dearer the deeper you go, and there are few faces. Always quote
|
||||
the whole-film average.
|
||||
|
||||
### Where the time goes (VR-015)
|
||||
|
||||
Measured over the whole film, 2026-08-04:
|
||||
|
||||
| node | cpu_s | % of pipeline CPU | cpu/f | exec/f | stall/f | in% | out% |
|
||||
|---|---|---|---|---|---|---|---|
|
||||
| **embedder** | **91.0** | **60%** | 17.74 | 21.61 | 3.87 | 12 | 0 |
|
||||
| **face_detector** ▶ | 41.4 | 27% | 8.07 | 24.20 | **16.14** | **99** | **0** |
|
||||
| frame_source | 12.1 | 8% | 2.36 | 11.26 | 8.90 | — | 97 |
|
||||
| camera_pos | 3.2 | 2% | 0.63 | 0.64 | 0.01 | 97 | 99 |
|
||||
| face_aligner | 1.7 | 1% | 0.33 | 0.34 | 0.01 | 0 | 12 |
|
||||
| identity_matcher | 1.3 | 1% | 0.26 | 0.34 | 0.09 | 0 | 0 |
|
||||
| tracker / sink | 0.5 | <1% | — | — | — | 0 | 0 |
|
||||
|
||||
**`face_detector` paces the run**: its input channel is 97.8% full while its
|
||||
output is 99.4% empty — everything upstream jammed, everything downstream
|
||||
starved. It occupies 5129 × 24.20 ms ≈ 124.1 s of a 124.2 s run, essentially
|
||||
100% wall occupancy, yet only 33% of that is CPU. The other 16.14 ms/frame is
|
||||
device wait.
|
||||
|
||||
**The embedder is the larger cost but not the constraint**: 60% of all pipeline
|
||||
CPU, 73% of wall as thread-busy. Whether that is real work or a spinning
|
||||
`cudaStreamSynchronize` is unresolved — see the sync caveat below, which is a
|
||||
one-line experiment.
|
||||
|
||||
**`frame_source` is the trap this table exists to defuse.** It reports
|
||||
`exec/f = 11.26 ms` against `cpu/f = 2.36 ms`, and its output channel is 97%
|
||||
full: it is backpressured, not expensive. The old KPN `ema` reading made it look
|
||||
like the most costly node in the pipeline at 141.899 ms/frame.
|
||||
|
||||
|
||||
`--benchmark <path>` writes a per-node timing report and prints a table at
|
||||
shutdown. `hero/run_bench.sh` is `run_trt.sh` with it switched on:
|
||||
|
||||
```bash
|
||||
./build/scene_analyze … --benchmark $H/bench_trt.json --output $H/pred_bench.json
|
||||
```
|
||||
|
||||
**Do not read the `ema` column of the old KPN diagnostics block as a cost.** KPN
|
||||
times a node across `fire_once`, which wraps the functor *and* the push to the
|
||||
next channel, and a push parks when that channel is full (AR-004). A
|
||||
backpressured node therefore bills its waiting to itself. On this film that
|
||||
produced a genuinely inverted answer:
|
||||
|
||||
```
|
||||
│ frame_source frames=5132 ema=141.899ms ← reported cost
|
||||
[frame_source] decode avg=16.6127ms fps=60.19 ← actual decode
|
||||
```
|
||||
|
||||
The source is not expensive; it is idle, holding a frame nobody has taken yet.
|
||||
Optimising against that number means optimising the fastest node in the graph.
|
||||
|
||||
The benchmark report separates the two:
|
||||
|
||||
| Column | Meaning | Blind spot |
|
||||
|---|---|---|
|
||||
| `cpu_s`, `cpu%tot` | thread CPU time, and this node's share of all of it | a GPU wait looks like idleness |
|
||||
| `cpu/f` | CPU ms per frame — backpressure cannot inflate it | as above |
|
||||
| `exec/f` | wall ms per frame in the node, **including parked pushes** | overstates a blocked node |
|
||||
| `stall/f` | `exec/f − cpu/f`: parked, or waiting on a device | does not say which |
|
||||
| `in%`, `out%` | mean fill of the node's input and output channels | — |
|
||||
| `press` | `in% − out%`; **the node marked ▶ is pacing the run** | not a cost, an ordering |
|
||||
|
||||
Read `press` first: work queues up in front of the bottleneck and starves
|
||||
everything after it, so the pacing node is the one with a full input and an empty
|
||||
output. Then read `cpu%run` to decide the repair — a saturated thread means the
|
||||
work itself must get cheaper, while an idle thread under pressure means the node
|
||||
is waiting on the GPU or the disk, where batch size and engine precision are the
|
||||
knobs and the C++ is not.
|
||||
|
||||
Channel fills are sampled every 100 ms (`--benchmark-interval-ms`) because
|
||||
`current_fill` is instantaneous: by shutdown every channel has drained, so a
|
||||
single read at the end reports an idle pipeline no matter how congested it was.
|
||||
|
||||
#### Check the GPU is not throttled before comparing anything
|
||||
|
||||
**On this hardware, thermal state moves the result more than any code change
|
||||
we are likely to make.** The same binary measured **8.25× cool and 3.12× once
|
||||
heat-soaked** — a 2.6× swing — because the laptop RTX 3050 hits `SW Thermal
|
||||
Slowdown` and pins the SM clock to **210 MHz out of 2100**:
|
||||
|
||||
```
|
||||
$ nvidia-smi -q -d PERFORMANCE | grep -E "SW Power Cap|SW Thermal"
|
||||
SW Power Cap : Active
|
||||
SW Thermal Slowdown : Active
|
||||
```
|
||||
|
||||
A number recorded without its clock state is not comparable to any other
|
||||
number, and back-to-back full-film runs guarantee the later ones are throttled.
|
||||
`run_bench.sh` now records `nvidia-smi` either side of the run into
|
||||
`bench_gpu.txt`; check it before believing a regression. Let the GPU idle back
|
||||
to full clock between measurements, and never A/B two runs across a heat-soak.
|
||||
|
||||
This one cost real time here: a 2.7× "regression" was attributed to a code
|
||||
change and reverted on that basis, when the change was innocent and the GPU had
|
||||
simply warmed up between the two measurements.
|
||||
|
||||
#### `cpu_s` on a GPU node is mostly spin — measured
|
||||
|
||||
CUDA's default sync policy (`cudaDeviceScheduleAuto`) spin-waits before it
|
||||
yields, so `cudaStreamSynchronize` charges the *calling thread's* CPU while the
|
||||
GPU works. A GPU-bound node therefore reports a large `cpu_s` and reads as
|
||||
CPU-bound.
|
||||
|
||||
`SAE_CUDA_BLOCKING_SYNC=1` switches to a blocking wait. Measured over 300 s of
|
||||
film, four cases, identical otherwise:
|
||||
|
||||
| case | realtime | total CPU | embedder CPU |
|
||||
|---|---|---|---|
|
||||
| baseline | 3.29× | 103 s | 66 s |
|
||||
| **`SAE_CUDA_BLOCKING_SYNC=1`** | 3.29× | **23 s** | **4 s** |
|
||||
| `SAE_CV_THREADS=1` | 3.30× | 101 s | 66 s |
|
||||
| both | 3.29× | 25 s | 5 s |
|
||||
|
||||
**94% of the embedder's CPU was spin, not work**, and 78% of the pipeline's.
|
||||
Throughput is unchanged, so this is free CPU — which matters for a service
|
||||
sharing a box (DP-003) and makes `cpu_s` mean what it says. Prefer it for any
|
||||
run where the CPU numbers are being read.
|
||||
|
||||
`SAE_CV_THREADS=1` does nothing measurable: the only OpenCV-heavy node is
|
||||
`face_aligner` at 1-2% of the pipeline, so the TBB arena is not worth removing
|
||||
and `warpAffine` is not worth replacing.
|
||||
|
||||
**Caveat: measured with the GPU clamped at 210 MHz** (see below). A device at
|
||||
full clock spends less time in the sync, so the absolute spin figure will fall;
|
||||
the ranking should not.
|
||||
|
||||
#### `cpu_s` counts one thread — mind the TBB arena
|
||||
|
||||
OpenCV 5 here is built against TBB, and every OpenCV module links it, so
|
||||
`cv::parallel_for_` dispatches onto a TBB arena of `nproc − 1` workers (19 on the
|
||||
20-core dev box; visible as `libtbb.so.12` frames in a thread dump). Since
|
||||
`CLOCK_THREAD_CPUTIME_ID` is per-thread, work a node fans out that way is billed
|
||||
to the TBB workers, **not** to the node.
|
||||
|
||||
So a node using `warpAffine`, a histogram compare or a colour conversion reads
|
||||
cheaper in `cpu_s` than it really is, and the missing time appears in `stall/f`,
|
||||
where it looks identical to a GPU wait. `exec/f` does capture it — the functor
|
||||
does not return until the parallel region joins — so the tell is a node whose
|
||||
`exec/f` far exceeds its `cpu/f` **while its output channel is empty**: that is
|
||||
fan-out, not blocking.
|
||||
|
||||
Worth knowing for its own sake, too: 9 KPN node threads plus 19 TBB workers plus
|
||||
the CUDA and NVDEC threads is heavy oversubscription on 20 cores.
|
||||
|
||||
The JSON carries the same data plus the run's configuration, so two runs can be
|
||||
diffed directly — which is the point, when sweeping `--embed-batch`, `--fps` or
|
||||
an engine precision.
|
||||
|
||||
### Check you are on the GPU
|
||||
|
||||
|
||||
Reference in New Issue
Block a user