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) <noreply@anthropic.com>
This commit is contained in:
@@ -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<double>(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
|
||||
|
||||
@@ -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);
|
||||
|
||||
@@ -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())
|
||||
|
||||
Reference in New Issue
Block a user