Files
dtourolle a5ee3c05ce 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
2026-08-05 14:38:15 +02:00

15 KiB
Raw Permalink Blame History

Benchmark — SuperHero

The reference film for end-to-end accuracy. Replaces Road to Bali, which was withdrawn for the reason in Why not Road to Bali.

TRACES: AR-011, AR-012, AR-013 | VR-001, VR-005 | SR-002


The film

SuperHero, from the NIST TRECVID Deep Video Understanding development set. 14 films are asserted Creative Commons and need no data agreement; only the 5 KinoLorber test films are gated.

Runtime 1025.5 s (17.1 min), 10 scenes
Resolution 640×360
Ground truth Per-scene presence, from the scene knowledge graphs
Gallery 5 characters, 14 references

The DVU set is what makes this workable: it ships character face crops cut from the film itself, so ground truth and gallery are both in character space and scoring needs no actor→character mapping.

Licence caveat. NIST links licence evidence for only 4 of the 14 films, and SuperHero is not one of them — its end credits carry no copyright or CC notice, list a "Temporary Musical Score" and a SAG cast, and it has no traceable online release. Fine for internal benchmarking; do not redistribute frames from it. Valkaama is the one film with an independently documented licence (CC BY-SA 3.0) if provenance ever has to be defended.


Reproducing it

# 1. Annotations, character mugshots, scene segmentation.
#    NIST names the same film three different ways, hence the overrides.
KG_DIR=superHero KG_FILE=superhero scripts/fetch_dvu.sh SuperHero ../dvu-hero

# 2. Scene clips (movie.shots), then fuse them into one stream.
#    Fusing matters — see "Run it as one film" below.
#    SuperHero-1.webm … SuperHero-10.webm from
#    <dataset>/movie.shots/, then:
ffmpeg -f concat -safe 0 -i concat.txt -c copy SuperHero_full.webm

# 3. Gallery, with the face-size floor that keeps references in distribution.
./build/build_gallery --root ../dvu-hero/root \
    --output ../dvu-hero/hero66.h5 --min-face-px 66

# 4. Run, on the GPU path (see "Check you are on the GPU").
./build/scene_analyze --movie hero/SuperHero_full.webm \
    --gallery ../dvu-hero/hero66.h5 \
    --detector-engine trt_cache/scrfd.scrfd_500m_bnkps.640.fp16.engine \
    --arcface-engine  trt_cache/arcface.LVFace-B_Glint360K.b4.fp16.engine \
    --fps 5 --min-face-px 32 --expand-gallery \
    --output pred.json

Nothing here is in git: the clips are ~130 MB and the annotations are regenerable. Replay fixtures derived from the run ship through the artifact registry instead:

scripts/artifacts/push_artifacts.sh replay-fixtures
scripts/artifacts/pull_artifacts.sh replay-fixtures [version]

The gallery travels in the same archive as the dumps deliberately — a dump only replays meaningfully against the gallery it was produced with, and pairing one with a different gallery silently changes every identity decision in it.


Results

Measured on the fused film, gallery expansion on.

Metric Value
Precision 1.00
Recall 0.65
F1 0.79
True positives 13
False positives 0
False negatives 7

Six of ten scenes scored exactly right, including the three-character scenes 4 and 5.

Zero false positives is the result worth keeping. Every out-of-gallery character — Beast, Mighty Celestial, Ms. Johnson, Doctor, two Masked Persons — was declined rather than forced onto a nearest match. That is the calibrated probability (AR-024) doing its job, and it is the right failure direction for an X-Ray overlay: a miss is a gap, an invention is a lie.

The misses have a shape. Scenes 1, 2, 3 and 8 were missed, and 13 are the three shortest scenes in the film (14 s, 38 s, 27 s). That is consistent with per-track Bayesian accumulation (AR-025) needing enough sightings before belief crosses threshold. Scene 8 is 65 s and does not fit that story — it is the one to look at first when improving recall.

Running the same scenes as isolated clips did not do better, so cross-scene gallery expansion is not currently compensating for short scenes.

Run it as one film, not as clips

Per-scene clips defeat per-film gallery expansion (AR-019), which grows a temporary gallery from track continuity across the whole film and re-assesses unknown tracks at the end. Ten isolated clips give it nothing to work with, and pay model and gallery load ten times over.

Fusing also makes presence windows cross real scene boundaries, which is how SR-002's scene-scoped question is asked in production. Note the joins are artificial cuts — consecutive scenes were never contiguous footage — so presence bleeding across a boundary may be the join rather than a tracking fault.


Throughput

Path Realtime factor Sampled fps 17-min film
build/ (TensorRT) 8.25× 41.3 2.1 min
build-ort/ (ORT) 0.54× 2.7 ~32 min

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:

./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

ORT's CUDA execution provider fails to load on this machine and silently falls back to CPU:

Failed to load library libonnxruntime_providers_cuda.so:
  undefined symbol: cudnnGetConvolutionBackwardDataAlgorithm_v7

That symbol was removed in cuDNN 9; the packaged ORT is built against cuDNN 8. ORT logs this once at startup and then runs happily on CPU, so a build-ort timing is a CPU number wearing a GPU label — a 15× error with no symptom other than a figure you have no baseline for. Grep the log for Failed to load library before trusting any throughput measurement.

The TensorRT path (build/) needs prebuilt engines from scripts/build_trt_engines.sh and reports what it loaded:

[TrtScrfd] loaded: … [TrtArcFace] loaded: … max_batch=4
[similarity] cuBLAS/CUDA engine: gallery resident on GPU

Why not Road to Bali

Bali was chosen because DVU ships character mugshots for it. It was withdrawn on face scale, measured on its own reference crops:

Bali SuperHero
Median detected face 27 px 69 px
Maximum detected face 69 px 241 px
References ≥66 px 2 of 69 14 of 27

The DVU images are scene crops, not mugshots, so the crop dimensions say nothing about face scale — the face has to be detected and measured. Bali's median reference was being upscaled roughly 4× to reach ArcFace's 112×112, and the worst 7×, which violates AR-011: every model gets the input it was trained for. A model run off-distribution returns confident, plausible, wrong output.

In a gallery that error is permanent. A bad frame costs one frame; a poisoned reference corrupts every future match against that identity.

No threshold rescued it. At 66 px only 2 of 69 references survived — the largest face in the entire set is 69 px — so there was no cut that both kept references in distribution and left enough of them to calibrate. SuperHero's gallery builds at a 66 px floor and calibrates on its own (a=15.2867 b=-4.98633, 100 % train accuracy) rather than borrowing constants.

Any accuracy figure recorded against Bali predates this and should be treated as measuring upscaling artifacts as much as the pipeline.