From bfb8cb813cfbdd094de2f3fef3f7af28ea967779 Mon Sep 17 00:00:00 2001 From: Filip Leonarski Date: Sat, 1 Aug 2026 14:49:45 +0200 Subject: [PATCH] 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) --- rugnux/Rugnux.cpp | 6 ++++++ rugnux/Rugnux.h | 3 +++ rugnux/rugnux_cli.cpp | 41 ++++++++++++++++++++++++++++++++++------- 3 files changed, 43 insertions(+), 7 deletions(-) diff --git a/rugnux/Rugnux.cpp b/rugnux/Rugnux.cpp index 752fd298..e509dcda 100644 --- a/rugnux/Rugnux.cpp +++ b/rugnux/Rugnux.cpp @@ -957,10 +957,16 @@ ProcessResult Rugnux::RunPipeline(RugnuxObserver *observer, bool write_output, b : std::function(azint_worker); std::vector > 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( + std::chrono::steady_clock::now() - image_loop_start).count(); result.cancelled = cancelled_; result.images_processed = finished_count.load(); diff --git a/rugnux/Rugnux.h b/rugnux/Rugnux.h index faa63c84..7d524d7a 100644 --- a/rugnux/Rugnux.h +++ b/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 indexing_rate; diff --git a/rugnux/rugnux_cli.cpp b/rugnux/rugnux_cli.cpp index b94666f2..5f75fe6b 100644 --- a/rugnux/rugnux_cli.cpp +++ b/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(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);