From 29eda90190679cff9713d404cbfdcedcc6cca0d1 Mon Sep 17 00:00:00 2001 From: Filip Leonarski Date: Mon, 24 Aug 2026 13:11:24 +0200 Subject: [PATCH] Report the time the whole run took, not the last pass of it processing_time_s is set inside RunPipeline, so it measures one pass. A rotation two-pass run integrates everything twice and the beam-stop / beam-centre pre-scan happens before either pass, none of which the reported number saw: on an 18 Mpx dataset it printed 7.58 s for a run that took 23.46 s. Time the run in Run(), where every pass is inside, and report that. The last pass is still printed alongside it when there was more than one, because the gap between them is what the second pass costs. The frame rate and throughput stay per-pass: they say how fast rugnux moves through images, which running a second pass does not change. Co-Authored-By: Claude Opus 5 (1M context) --- rugnux/Rugnux.cpp | 10 ++++++++++ rugnux/Rugnux.h | 7 +++++++ rugnux/rugnux_cli.cpp | 12 +++++++++--- 3 files changed, 26 insertions(+), 3 deletions(-) diff --git a/rugnux/Rugnux.cpp b/rugnux/Rugnux.cpp index a0af6c12..50d89b81 100644 --- a/rugnux/Rugnux.cpp +++ b/rugnux/Rugnux.cpp @@ -812,6 +812,16 @@ void Rugnux::RefineStillsGeometry(int start_image, int end_image, int images_to_ } ProcessResult Rugnux::Run(RugnuxObserver *observer) { + // Each pass times only itself, so the canonical result's processing_time_s is the last pass alone - + // on the rotation two-pass that is under a third of what the run actually took, the pre-scan and the + // first pass being invisible in it. Time the whole thing here, where every pass is inside. + const auto run_start = std::chrono::steady_clock::now(); + ProcessResult result = RunAllPasses(observer); + result.total_time_s = std::chrono::duration(std::chrono::steady_clock::now() - run_start).count(); + return result; +} + +ProcessResult Rugnux::RunAllPasses(RugnuxObserver *observer) { // Rotation two-pass geometry post-refinement: the first pass integrates at the header geometry and // post-refines the detector geometry (distance + beam from the observed spot positions, cell scale + axis // from phi_obs); the second pass re-indexes and re-integrates with the refined geometry. Only the second diff --git a/rugnux/Rugnux.h b/rugnux/Rugnux.h index 55253fc8..ed4a8307 100644 --- a/rugnux/Rugnux.h +++ b/rugnux/Rugnux.h @@ -131,6 +131,10 @@ struct ProcessResult { // 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; + // Wall time of the WHOLE run: every pass the rotation two-pass ran, plus the beam-stop / + // beam-centre pre-scan that runs before the first one. processing_time_s is the last pass alone + // and so understates a two-pass run by more than a factor of two. + double total_time_s = 0.0; // Workers the per-image loop actually ran, which is not config.nthreads once the loop is capped. int image_loop_threads = 0; double frame_rate_hz = 0.0; @@ -293,6 +297,9 @@ class Rugnux { // and applies it (+ the refined lattice) to experiment_, so the next pass re-integrates with it. ProcessResult RunPipeline(RugnuxObserver *observer, bool write_output, bool geometry_prepass); + // Every pass of the run, returning the canonical one. Run() wraps this to time the whole thing. + ProcessResult RunAllPasses(RugnuxObserver *observer); + public: Rugnux(JFJochHDF5Reader &reader, DiffractionExperiment experiment, PixelMask pixel_mask, ProcessConfig config); diff --git a/rugnux/rugnux_cli.cpp b/rugnux/rugnux_cli.cpp index 90e7b135..8fcad8ef 100644 --- a/rugnux/rugnux_cli.cpp +++ b/rugnux/rugnux_cli.cpp @@ -1665,7 +1665,7 @@ static int RunRugnux(int argc, char **argv) { } g_active_process = nullptr; - std::cout << fmt::format("Processing time: {:.2f} s", result.processing_time_s) << std::endl; + std::cout << fmt::format("Processing time: {:.2f} s", result.total_time_s) << std::endl; std::cout << fmt::format("Frame rate: {:.2f} Hz", result.frame_rate_hz) << std::endl; std::cout << fmt::format("Total throughput: {:.2f} MB/s", result.throughput_MBs) << std::endl; if (result.cancelled) @@ -2144,8 +2144,14 @@ static int RunRugnux(int argc, char **argv) { if (!result.merge_statistics_text.empty()) std::cout << std::endl << result.merge_statistics_text << std::endl; - // Report statistics - std::cout << fmt::format("Processing time: {:.2f} s", result.processing_time_s) << std::endl; + // Report statistics. The time is the whole run - a rotation two-pass integrates everything twice, + // and the pre-scan runs before either pass, so the per-pass number understated it by 3-4x. The rate + // and throughput stay per-pass: they say how fast rugnux moves through images, which running a + // second pass does not change. + std::cout << fmt::format("Processing time: {:.2f} s", result.total_time_s) << std::endl; + if (result.pass_count > 1) + std::cout << fmt::format(" last pass: {:.2f} s (of {} passes)", + result.processing_time_s, result.pass_count) << std::endl; std::cout << fmt::format("Frame rate: {:.2f} Hz", result.frame_rate_hz) << std::endl; std::cout << fmt::format("Total throughput:{:.2f} MB/s", result.throughput_MBs) << std::endl; if (result.indexing_rate.has_value())