diff --git a/rugnux/rugnux_cli.cpp b/rugnux/rugnux_cli.cpp index 09af6a62..fedc5e09 100644 --- a/rugnux/rugnux_cli.cpp +++ b/rugnux/rugnux_cli.cpp @@ -2176,28 +2176,36 @@ static int RunRugnux(int argc, char **argv) { 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. + // BLOCKED on a contended resource - above all the GPU - as well as its own work. Dividing that by + // the worker count, as this used to, assumes every worker was busy for the whole loop; the loop + // in fact runs at a fraction of the workers it was given (a third of them on a large detector, + // less on a small one), so the printed cost came out low by that same factor. + // + // Report the share instead. A stage's fraction of a worker's own per-image time is what that + // stage is responsible for, whatever the contention was, and spending it against the loop's wall + // time per image gives a number that is attributable and that sums to the loop. The worker mean + // itself is printed at the end, because the gap between it and the wall is the waiting, and that + // is worth seeing rather than dividing away. const auto &t = result.mean_processing_time; - const double per_worker = std::max(1, nthreads); + const double loop_ms = (result.images_processed > 0 && result.image_loop_time_s > 0.0) + ? result.image_loop_time_s * 1e3 / static_cast(result.images_processed) : 0.0; + const double worker_mean_ms = std::isfinite(t.processing) ? t.processing * 1e3 : 0.0; 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(); + return (std::isfinite(mean_s) && worker_mean_ms > 0.0) + ? fmt::format(" {} {:.2f}", name, mean_s * 1e3 / worker_mean_ms * loop_ms) : std::string(); }; - std::cout << fmt::format("Per-image cost (ms, {} workers):", nthreads) + std::cout << fmt::format("Per-image cost (ms of loop wall, {} 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; + << stage("total", t.processing) + << fmt::format(" [{:.1f} ms inside a worker; the difference is waiting]", worker_mean_ms) + << 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