rugnux: report per-image cost honestly instead of per-worker blocked time

Each stage timer measures wall time inside one worker, so it counts whatever that
worker spent blocked on a contended resource - above all the single GPU - as well
as its own work. Those waits overlap across workers, so the mean was printed as if
it were the per-image cost when it is roughly the per-image cost times the worker
count. At the default thread count on a large detector the reported total came out
more than twenty times the truth, and single stages were printed as several times
the entire per-image budget of the run. That is the one output anyone tuning
performance reads, and it sent this investigation at the wrong stage for a while.

Divide by the worker count. It is a lower bound - a worker idle rather than blocked
is not counted - so rather than hide the remainder, report the image loop's own wall
time next to it, and with it the time spent OUTSIDE the loop. Nothing measured the
latter before, yet on a rotation run the first-pass indexing and the scaling and
merging can be more of the run than the per-image work is: on a large-detector run
here it is 5.1 s against 3.0 s. Both figures are for the last pass, and a two-pass
rotation run does all of it twice.

Also stop printing nan. The per-image indexing and scaling timers are never fed on
the two-pass rotation path, because the lattice is forced rather than searched per
image and the merge happens outside the loop, so every default rotation run reported
"indexing nan scaling nan". A stage that did not run is now simply absent.

Measured against the loop's own wall clock on a 18 Mpx dataset: 5% at one worker,
11% at eight, 29% at thirty-two, versus 23x too high before.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

rugnux/Rugnux.cpp

@@ -957,10 +957,16 @@ ProcessResult Rugnux::RunPipeline(RugnuxObserver *observer, bool write_output, b
                                         : std::function<void()>(azint_worker);
     std::vector<std::future<void> > futures;
     futures.reserve(config_.nthreads);
+    const auto image_loop_start = std::chrono::steady_clock::now();
     for (int i = 0; i < config_.nthreads; ++i)
         futures.push_back(std::async(std::launch::async, worker));
     for (auto &f: futures)
         f.get();
+    // Wall time of the per-image loop alone. The per-stage means below cover only what runs inside it,
+    // so without this there is nothing to compare them against and no way to see how much of a run is
+    // spent outside it - on the first-pass indexing and on scaling/merging.
+    result.image_loop_time_s = std::chrono::duration<double>(
+            std::chrono::steady_clock::now() - image_loop_start).count();
 
     result.cancelled = cancelled_;
     result.images_processed = finished_count.load();

rugnux/Rugnux.h

@@ -99,6 +99,9 @@ struct ProcessResult {
     bool cancelled = false;
     uint64_t images_processed = 0;
     double processing_time_s = 0.0;
+    // Wall time of the per-image loop alone; processing_time_s additionally covers the first-pass
+    // indexing and the scaling/merging around it, which no per-stage timer sees.
+    double image_loop_time_s = 0.0;
     double frame_rate_hz = 0.0;
     double throughput_MBs = 0.0;
     std::optional<float> indexing_rate;

rugnux/rugnux_cli.cpp

@@ -1661,14 +1661,41 @@ static int RunRugnux(int argc, char **argv) {
     if (result.indexing_rate.has_value() && !anything_indexed)
         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.
     const auto &t = result.mean_processing_time;
-    std::cout << fmt::format(
-        "Per-image time (mean; ms): decompress {:.2f} preprocess {:.2f} azint {:.2f} spot finding {:.2f} "
-        "indexing {:.2f} refinement {:.2f} indexing analysis {:.2f} prediction {:.2f} integration {:.2f} "
-        "scaling {:.2f} total {:.2f}",
-        t.compression * 1e3, t.preprocessing * 1e3, t.azint * 1e3, t.spot_finding * 1e3,
-        t.indexing * 1e3, t.refinement * 1e3, t.indexing_analysis * 1e3, t.bragg_prediction * 1e3,
-        t.integration * 1e3, t.image_scale * 1e3, t.processing * 1e3) << std::endl;
+    const double per_worker = std::max(1, nthreads);
+    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();
+    };
+    std::cout << fmt::format("Per-image cost (ms, {} 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;
+
+    // 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
+    // whole run instead of leaving the difference unexplained. Both are the last pass only: a two-pass
+    // rotation run does all of this twice.
+    if (result.images_processed > 0 && result.image_loop_time_s > 0.0) {
+        const double loop_ms = result.image_loop_time_s * 1e3 / static_cast<double>(result.images_processed);
+        const double outside_s = result.processing_time_s - result.image_loop_time_s;
+        std::cout << fmt::format("Per-image wall:  {:.2f} ms in the image loop ({:.2f} s); "
+                                 "{:.2f} s outside it (first-pass indexing, scaling/merging) [last pass]",
+                                 loop_ms, result.image_loop_time_s, std::max(0.0, outside_s)) << std::endl;
+    }
 
     if (result.cancelled)
         logger.Warning("Processing was cancelled after {} images", result.images_processed);