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())