diff --git a/common/CUDAWrapper.cpp b/common/CUDAWrapper.cpp index ab3e2e6c..3cedde9d 100644 --- a/common/CUDAWrapper.cpp +++ b/common/CUDAWrapper.cpp @@ -1,14 +1,39 @@ // SPDX-FileCopyrightText: 2024 Filip Leonarski, Paul Scherrer Institute // SPDX-License-Identifier: GPL-3.0-only -#ifndef JFJOCH_USE_CUDA - #include "CUDAWrapper.h" +// Build-independent: the CUDA build gets get_gpu_names() from CUDAWrapper.cu, the CPU-only build from +// the stub below, and this collapses whichever list came back. Four identical cards read better as +// "4x " than as the same name four times, and a mixed machine keeps one group per model. +std::string get_gpu_description() { + const auto names = get_gpu_names(); + + std::string out; + for (size_t i = 0; i < names.size();) { + size_t n = 1; + while (i + n < names.size() && names[i + n] == names[i]) + n++; + if (!out.empty()) + out += ", "; + if (n > 1) + out += std::to_string(n) + "x "; + out += names[i]; + i += n; + } + return out; +} + +#ifndef JFJOCH_USE_CUDA + int32_t get_gpu_count() { return 0; } +std::vector get_gpu_names() { + return {}; +} + void set_gpu(int32_t dev_id) {} void pin_gpu() {} diff --git a/common/CUDAWrapper.cu b/common/CUDAWrapper.cu index 554c54c6..51e203cf 100644 --- a/common/CUDAWrapper.cu +++ b/common/CUDAWrapper.cu @@ -27,6 +27,22 @@ int32_t get_gpu_count() { } +std::vector get_gpu_names() { + std::vector names; + const int32_t count = get_gpu_count(); + names.reserve(count); + for (int32_t i = 0; i < count; i++) { + cudaDeviceProp prop{}; + // A device that cannot be queried still exists and still gets work, so it is listed - just + // without a name. Losing the whole list over one unreadable device would be worse. + if (cudaGetDeviceProperties(&prop, i) == cudaSuccess) + names.emplace_back(prop.name); + else + names.emplace_back("unknown GPU"); + } + return names; +} + void set_gpu(int32_t dev_id) { auto dev_count = get_gpu_count(); diff --git a/common/CUDAWrapper.h b/common/CUDAWrapper.h index 4b288ee0..ccbd4a75 100644 --- a/common/CUDAWrapper.h +++ b/common/CUDAWrapper.h @@ -4,8 +4,18 @@ #pragma once #include +#include +#include int32_t get_gpu_count(); + +// Names of the visible GPUs, in device order and one entry per device, so repeated cards repeat. +// Empty without CUDA and on a machine with no device, which is also what get_gpu_count() == 0 says. +std::vector get_gpu_names(); + +// The same list collapsed for a person: "4x NVIDIA A100-SXM4-80GB", or several such groups separated +// by ", " on a mixed machine. Empty when no GPU is visible. +std::string get_gpu_description(); void set_gpu(int32_t dev_id); // Pin the calling thread to the next GPU in round-robin order, using a process-wide counter diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index e2a2a912..3666d5ca 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -3,6 +3,8 @@ ### 1.0.0-rc.165 This is an UNSTABLE release. It includes many experimental features, as well as many AI generated fixes. We recommend using rc.152 for production use. +* The rugnux results report records how the run was invoked, what it cost and what it ran on: `COMMAND_LINE=` is the command line as one shell-ready line, `WALL_TIME=` the whole invocation in seconds, and `GPU_COUNT=` / `GPU=` how many GPUs were visible and which ones. The total wall time is also printed on stdout, next to the processing time it is slightly larger than. +* rugnux says which GPUs it can see before it starts processing, so a machine that turns out to have none - a driver mismatch, a leftover `CUDA_VISIBLE_DEVICES` - is noticed while there is still time to stop rather than after a run that took far longer than it should have. * rugnux writes `_unmerged.mtz` on every run that produces an output prefix, instead of only when asked for it with `--export-unmerged`. It is written in `--mode mx` and `--mode scale` and with `--no-merge`, alongside the merged files and replacing none of them. `--no-export-unmerged` turns it off. * `/start` asks the writer whether the run can be written before the detector is armed, so a run whose output file already exists, or whose output directory cannot be created, is refused up front with the writer's own message instead of failing once the detector is running. This needs the TCP image stream or the built-in HDF5 writer; the ZeroMQ stream has no way to answer and is unchanged. * An output data file already in the way is refused when the collection starts, not when the file is renamed into place at the end of it. diff --git a/docs/RUGNUX.md b/docs/RUGNUX.md index 95f5ba10..2e9e4fa9 100644 --- a/docs/RUGNUX.md +++ b/docs/RUGNUX.md @@ -533,6 +533,23 @@ structure a script can consume without parsing prose. `REPORT_VERSION=` is the format's own version. Key names, table columns and the reason vocabulary below are an interface other software may depend on: they do not change without that number moving. +Adding a key does not move it — a consumer that greps for what it needs is unaffected by one more +line. + +The header block above section 1 records **how the result was produced**: `RUGNUX_VERSION=` and +`RUGNUX_GIT=`, `DATE=`, `INPUT_FILE=` and `OUTPUT_PREFIX=`, plus + +- **`COMMAND_LINE=`** — the invocation as one shell-ready line, arguments containing spaces quoted. +- **`WALL_TIME=`** — the whole invocation in seconds. It covers everything the process did, opening + the file and setting up included, so it is a little larger than the `Processing time` printed on + stdout, which starts once the analysis does. +- **`GPU_COUNT=`** and **`GPU=`** — how many GPUs were visible and what they are, e.g. + `GPU= 4x NVIDIA A100-SXM4-80GB`; several models on one machine are listed as separate groups. + `GPU_COUNT= 0` appears on its own, with no `GPU=` line, when nothing was visible — which is the + first thing to check when a run took far longer than expected. rugnux prints the same line at + startup, before the run, so a missing GPU can be caught while there is still time to stop. + +Rates, per-image costs and progress remain on stdout only. Sections, in order: `1. DATA SET`, `2. INDEXING`, `3. GEOMETRY POST-REFINEMENT` (rotation only), `4. SPACE GROUP DETERMINATION`, `5. SCALING AND MERGING`, `6. TWINNING`, `7. RADIATION DAMAGE`, diff --git a/rugnux/ResultReport.cpp b/rugnux/ResultReport.cpp index 0dd65bf1..5aa4e2f3 100644 --- a/rugnux/ResultReport.cpp +++ b/rugnux/ResultReport.cpp @@ -41,7 +41,8 @@ namespace { std::string RenderResultReport(const std::string &output_prefix, const std::string &input_file, const DiffractionExperiment &experiment, - const ProcessResult &result) { + const ProcessResult &result, + const RunProvenance &provenance) { std::ostringstream os; const bool rotation = experiment.IsRotationIndexing(); const bool merged = result.has_merge_statistics; @@ -52,8 +53,8 @@ std::string RenderResultReport(const std::string &output_prefix, << BANNER << "\n\n" << " What this run determined, written next to its other output. The `KEY= value` lines and\n" << " the tables below are a stable interface - a script greps them, and REPORT_VERSION says\n" - << " when that interface last changed. Timing, rates and per-image progress are not here;\n" - << " they are on stdout.\n\n"; + << " when that interface last changed. Rates and per-image progress are not here; they are\n" + << " on stdout.\n\n"; Key(os, "REPORT_VERSION", REPORT_VERSION); Key(os, "RUGNUX_VERSION", jfjoch_version()); @@ -62,6 +63,20 @@ std::string RenderResultReport(const std::string &output_prefix, Key(os, "DATE", time_UTC(std::chrono::system_clock::now())); Key(os, "INPUT_FILE", input_file); Key(os, "OUTPUT_PREFIX", output_prefix); + // How the result was produced, what it cost and what it ran on, so the report stands on its own + // once the shell history it came from is gone. Absent rather than zero where the caller does not + // know them - the library and the viewer have no command line and no invocation to time. + if (!provenance.command_line.empty()) + Key(os, "COMMAND_LINE", provenance.command_line); + if (provenance.wall_time_s > 0.0) + Key(os, "WALL_TIME", fmt::format("{:.2f}", provenance.wall_time_s)); + if (provenance.gpu_count >= 0) { + Key(os, "GPU_COUNT", provenance.gpu_count); + // GPU_COUNT= 0 with no GPU= line is the CPU-only case, and saying so is the point: whether + // the GPUs were there is the first question about how long the run took. + if (!provenance.gpu_description.empty()) + Key(os, "GPU", provenance.gpu_description); + } // ---------------------------------------------------------------- 1. DATA SET Section(os, "1. DATA SET"); @@ -351,7 +366,8 @@ void WriteResultReport(const std::string &output_prefix, const std::string &input_file, const DiffractionExperiment &experiment, const ProcessResult &result, - Logger &logger) { + Logger &logger, + const RunProvenance &provenance) { if (output_prefix.empty()) return; // "compute the statistics, persist nothing" @@ -361,7 +377,7 @@ void WriteResultReport(const std::string &output_prefix, try { std::ofstream file(filename); file.exceptions(std::ios::failbit | std::ios::badbit); - file << RenderResultReport(output_prefix, input_file, experiment, result); + file << RenderResultReport(output_prefix, input_file, experiment, result, provenance); } catch (const std::exception &e) { logger.Warning("Could not write the results report {}: {}", filename, e.what()); } diff --git a/rugnux/ResultReport.h b/rugnux/ResultReport.h index be4424c6..566e53b1 100644 --- a/rugnux/ResultReport.h +++ b/rugnux/ResultReport.h @@ -12,16 +12,30 @@ // _report.txt - what the run DETERMINED, written next to the .mtz/.cif/.hkl on every run // that has an output prefix. Modelled on XDS's CORRECT.LP: prose and tables a crystallographer // reads top to bottom, with `KEY= value` assignment lines and fixed-width tables a script greps -// without parsing prose. Timing, rates and progress are deliberately absent - those are stdout. +// without parsing prose. Rates and per-image progress are deliberately absent - those are stdout; +// the command line and the total wall time are here, because they say how this result was produced +// and a report that has to be read next to a lost shell history is worth less. // // The format is an interface: key names, table columns and the reason vocabulary are stable, and // REPORT_VERSION is bumped if they ever change. See docs/RUGNUX.md. +// How the run was produced: the invocation, what it cost, and what it ran on. The CLI is the only +// caller that knows these, so they are passed in rather than read here. Each is left out of the +// report when it is not given - a caller that cannot supply one must not have the report claim the +// run was invoked by nobody, took no time, or saw no GPU. +struct RunProvenance { + std::string command_line; // argv as one shell-ready line + double wall_time_s = 0.0; // the whole invocation; 0 = not measured + int32_t gpu_count = -1; // -1 = not reported; 0 is a statement, not an omission + std::string gpu_description; // "4x NVIDIA A100-SXM4-80GB"; empty when there is no GPU +}; + // Renders the report. Exposed for testing; RunPipeline results are the only input. std::string RenderResultReport(const std::string &output_prefix, const std::string &input_file, const DiffractionExperiment &experiment, - const ProcessResult &result); + const ProcessResult &result, + const RunProvenance &provenance = {}); // Renders and writes _report.txt. Does nothing when the prefix is empty (the // "compute statistics, persist nothing" mode). Never throws: a run that produced good reflections @@ -30,4 +44,5 @@ void WriteResultReport(const std::string &output_prefix, const std::string &input_file, const DiffractionExperiment &experiment, const ProcessResult &result, - Logger &logger); + Logger &logger, + const RunProvenance &provenance = {}); diff --git a/rugnux/rugnux_cli.cpp b/rugnux/rugnux_cli.cpp index 47de51ee..ac9c8827 100644 --- a/rugnux/rugnux_cli.cpp +++ b/rugnux/rugnux_cli.cpp @@ -23,6 +23,7 @@ #include "../common/DiffractionExperiment.h" #include "../common/PixelMask.h" #include "../common/print_license.h" +#include "../common/CUDAWrapper.h" #include "../common/JFJochMath.h" #include "../image_analysis/bragg_integration/CalcISigma.h" #include "../image_analysis/geom_refinement/Calibrants.h" @@ -566,6 +567,31 @@ namespace { if (auto *p = g_active_process.load()) p->Cancel(); } + + // argv as one line, echoed at the top of the run and recorded in the results report. An argument + // that would not survive being pasted back into a shell is single-quoted, so a file prefix with a + // space in it comes back as the one argument it was. + std::string JoinCommandLine(int argc, char **argv) { + std::string out; + for (int i = 0; i < argc; i++) { + if (i > 0) + out += ' '; + const std::string arg = argv[i]; + if (arg.find_first_of(" \t\n'\"\\$`*?()[]{}<>|&;#~") == std::string::npos) { + out += arg; + continue; + } + out += '\''; + for (char c : arg) { + if (c == '\'') + out += "'\\''"; + else + out += c; + } + out += '\''; + } + return out; + } } // The body of main. Settings setters and the pipeline itself throw JFJochException on input the parser @@ -573,11 +599,24 @@ namespace { // an unreadable file), so main wraps this and reports rather than letting the exception terminate the // process with no diagnostic and exit code 134. static int RunRugnux(int argc, char **argv) { - for (int i = 0; i < argc; i++) { - std::cout << argv[i] << " "; - } - std::cout << std::endl << std::endl; + // The whole invocation, reported at the end and written into the results report. Started before + // anything else so it covers reading the file and setting up as well as the processing. + const auto invocation_start = std::chrono::steady_clock::now(); + RunProvenance provenance; + provenance.command_line = JoinCommandLine(argc, argv); + provenance.gpu_count = get_gpu_count(); + provenance.gpu_description = get_gpu_description(); + std::cout << provenance.command_line << std::endl << std::endl; + // Said before the run rather than after it: the GPUs are what makes rugnux fast, and a machine + // that turns out to have none - a driver mismatch, a CUDA_VISIBLE_DEVICES left over from another + // job - is worth knowing about while there is still time to stop and fix it. + if (provenance.gpu_count > 0) + std::cout << fmt::format("GPU: {} ({} visible)", + provenance.gpu_description, provenance.gpu_count) << std::endl; + else + std::cout << "GPU: none visible - running on the CPU, which is much slower" + << std::endl; RegisterHDF5Filter(); @@ -1698,7 +1737,10 @@ static int RunRugnux(int argc, char **argv) { scale_result.error_model_b = error_model_b; scale_result.has_reference = !reference_data.empty(); scale_result.twinning = twinning; - WriteResultReport(output_prefix, input_file, experiment, scale_result, logger); + provenance.wall_time_s = std::chrono::duration( + std::chrono::steady_clock::now() - invocation_start).count(); + std::cout << fmt::format("Total wall time: {:.2f} s", provenance.wall_time_s) << std::endl; + WriteResultReport(output_prefix, input_file, experiment, scale_result, logger, provenance); return 0; } @@ -2292,7 +2334,11 @@ static int RunRugnux(int argc, char **argv) { // The results report, next to the .mtz/.cif/.hkl. Written on every run with an output prefix - // including --no-merge, which still determined an indexing and geometry result worth recording. - WriteResultReport(output_prefix, input_file, experiment, result, logger); + // The wall time is the whole invocation, which is more than result.total_time_s: that one starts + // inside Rugnux::Run, so it counts neither opening the file nor setting up the analysis. + provenance.wall_time_s = std::chrono::duration( + std::chrono::steady_clock::now() - invocation_start).count(); + WriteResultReport(output_prefix, input_file, experiment, result, logger, provenance); // The space-group search is rendered here (not in the library) so the viewer does not emit it on // stdout and the CLI owns the format. @@ -2307,6 +2353,7 @@ static int RunRugnux(int argc, char **argv) { // 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; + std::cout << fmt::format("Total wall time: {:.2f} s", provenance.wall_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; diff --git a/tests/ResultReportTest.cpp b/tests/ResultReportTest.cpp index d25c0e18..57e3c698 100644 --- a/tests/ResultReportTest.cpp +++ b/tests/ResultReportTest.cpp @@ -7,6 +7,7 @@ #include "../image_analysis/scale_merge/Merge.h" #include "../reader/JFJochHDF5Reader.h" #include "../rugnux/ResultReport.h" +#include "../common/CUDAWrapper.h" #include "../writer/FileWriter.h" // Two synthetic ranges, one of each shape the report has to handle. @@ -182,3 +183,56 @@ TEST_CASE("SweepQuality_HDF5RoundTrip", "[HDF5][Full][Diagnostics]") { REQUIRE(H5Fget_obj_count(H5F_OBJ_ALL, H5F_OBJ_ALL) == 0); remove("sweep_quality_roundtrip_master.h5"); } + +// The command line, the wall time and the GPUs say how the result was produced, what it cost and what +// it ran on, so the report can be read on its own once the shell history is gone. They come from the +// CLI, which is the only caller that knows them; a caller that does not - the library, the viewer - +// must get a report without them rather than one claiming the run was invoked by nobody, took no +// time, and saw no GPU. +TEST_CASE("ResultReport_ProvenanceKeys", "[Diagnostics]") { + DiffractionExperiment x(DetJF(1)); + x.ImagesPerTrigger(600); + + ProcessResult result; + result.images_processed = 600; + result.consensus_cell = UnitCell{.a = 79.0f, .b = 79.0f, .c = 38.0f, + .alpha = 90.0f, .beta = 90.0f, .gamma = 90.0f}; + + RunProvenance provenance; + provenance.command_line = "rugnux -o prefix in.h5"; + provenance.wall_time_s = 262.409; + provenance.gpu_count = 4; + provenance.gpu_description = "4x NVIDIA A100-SXM4-80GB"; + + const auto text = RenderResultReport("prefix", "in.h5", x, result, provenance); + CHECK(text.find("\nCOMMAND_LINE= rugnux -o prefix in.h5\n") != std::string::npos); + CHECK(text.find("\nWALL_TIME= 262.41\n") != std::string::npos); + CHECK(text.find("\nGPU_COUNT= 4\n") != std::string::npos); + CHECK(text.find("\nGPU= 4x NVIDIA A100-SXM4-80GB\n") != std::string::npos); + + // A machine with no GPU says so - GPU_COUNT= 0 is a statement about why the run took as long as + // it did, and only the name list has nothing to report. + RunProvenance cpu_only; + cpu_only.gpu_count = 0; + const auto cpu_text = RenderResultReport("prefix", "in.h5", x, result, cpu_only); + CHECK(cpu_text.find("\nGPU_COUNT= 0\n") != std::string::npos); + CHECK(cpu_text.find("\nGPU= ") == std::string::npos); + + const auto without = RenderResultReport("prefix", "in.h5", x, result); + CHECK(without.find("COMMAND_LINE=") == std::string::npos); + CHECK(without.find("WALL_TIME=") == std::string::npos); + CHECK(without.find("GPU_COUNT=") == std::string::npos); +} + +// get_gpu_description collapses repeats, so a four-card machine reads as one line rather than the +// same name four times. Build-independent: without CUDA there are no names and it is empty. +TEST_CASE("ResultReport_GpuDescription", "[Diagnostics]") { + const auto names = get_gpu_names(); + CHECK(names.size() == static_cast(std::max(0, get_gpu_count()))); + + const auto description = get_gpu_description(); + if (names.empty()) + CHECK(description.empty()); + else + CHECK(description.find(names.front()) != std::string::npos); +}