Report the per-image cost as something that can be attributed

Each stage timer is wall time inside one worker, so it counts whatever that worker spent blocked -
on the GPU, above all - as well as its own work. Dividing the mean by the worker count, as this did,
assumes every worker was busy for the whole loop. Measured occupancy is a third of the workers asked
for on a large detector and less on a small one, so the number people tune against came out low by
that factor, and it moved with the contention rather than with the work.

Report the share instead. A stage's fraction of a worker's own per-image time is what that stage is
responsible for whatever the contention was, and spending that fraction against the loop's wall time
per image gives a figure that is attributable and that sums to the loop. The worker mean is printed
at the end rather than divided away, because the gap between it and the wall is the waiting, and the
size of that gap is worth seeing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_011n8riB6X59oRjkrSHzNPAU

rugnux/rugnux_cli.cpp

@@ -2176,28 +2176,36 @@ static int RunRugnux(int argc, char **argv) {
         std::cout << "No image indexed - no crystal lattice was determined from this dataset" << std::endl;
 
     // Each stage timer measures wall time inside one worker, so it counts the time that worker spent
-    // BLOCKED on a contended resource - above all the single GPU - as well as its own work. With N
-    // workers those waits overlap, so the per-image cost is the worker mean divided by the worker
-    // count, not the mean itself: printed raw at 32 workers these numbers overstate the truth by more
-    // than an order of magnitude, which is exactly backwards for the one output people tune against.
-    // Dividing is a lower bound (a worker that is idle rather than blocked is not counted), so the
-    // remainder is shown against the loop's own wall time rather than hidden.
+    // BLOCKED on a contended resource - above all the GPU - as well as its own work. Dividing that by
+    // the worker count, as this used to, assumes every worker was busy for the whole loop; the loop
+    // in fact runs at a fraction of the workers it was given (a third of them on a large detector,
+    // less on a small one), so the printed cost came out low by that same factor.
+    //
+    // Report the share instead. A stage's fraction of a worker's own per-image time is what that
+    // stage is responsible for, whatever the contention was, and spending it against the loop's wall
+    // time per image gives a number that is attributable and that sums to the loop. The worker mean
+    // itself is printed at the end, because the gap between it and the wall is the waiting, and that
+    // is worth seeing rather than dividing away.
     const auto &t = result.mean_processing_time;
-    const double per_worker = std::max(1, nthreads);
+    const double loop_ms = (result.images_processed > 0 && result.image_loop_time_s > 0.0)
+            ? result.image_loop_time_s * 1e3 / static_cast<double>(result.images_processed) : 0.0;
+    const double worker_mean_ms = std::isfinite(t.processing) ? t.processing * 1e3 : 0.0;
     auto stage = [&](const char *name, float mean_s) {
         // A stage that never ran has no mean at all - the per-image indexing and scaling timers are
         // never fed on the two-pass rotation path, where the lattice is forced and the merge happens
         // outside the image loop. Say nothing rather than printing nan.
-        return std::isfinite(mean_s)
-               ? fmt::format(" {} {:.2f}", name, mean_s * 1e3 / per_worker) : std::string();
+        return (std::isfinite(mean_s) && worker_mean_ms > 0.0)
+               ? fmt::format(" {} {:.2f}", name, mean_s * 1e3 / worker_mean_ms * loop_ms) : std::string();
     };
-    std::cout << fmt::format("Per-image cost (ms, {} workers):", nthreads)
+    std::cout << fmt::format("Per-image cost (ms of loop wall, {} workers):", nthreads)
               << stage("decompress", t.compression) << stage("preprocess", t.preprocessing)
               << stage("azint", t.azint) << stage("spot-finding", t.spot_finding)
               << stage("indexing", t.indexing) << stage("refinement", t.refinement)
               << stage("indexing-analysis", t.indexing_analysis) << stage("prediction", t.bragg_prediction)
               << stage("integration", t.integration) << stage("scaling", t.image_scale)
-              << stage("total", t.processing) << std::endl;
+              << stage("total", t.processing)
+              << fmt::format("   [{:.1f} ms inside a worker; the difference is waiting]", worker_mean_ms)
+              << std::endl;
 
     // The stage timers only cover the per-image loop. On a rotation run the first-pass indexing and the
     // scaling/merging sit outside it and can be a large share of the run, so report the loop against the