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