diff --git a/broker/JFJochStateMachine.cpp b/broker/JFJochStateMachine.cpp index 1515d419..3c9b54cf 100644 --- a/broker/JFJochStateMachine.cpp +++ b/broker/JFJochStateMachine.cpp @@ -409,13 +409,14 @@ void JFJochStateMachine::MeasurementThread() { scan_result = tmp_output.receiver_output.scan_result; auto image_mean_time = tmp_output.receiver_output.processing_time; - logger.Info("Per-image processing time: (mean; microseconds): compression {:.0f} preprocess {:.0f} azint {:.0f} spot finding {:.0f} indexing {:.0f} refinement {:.0f} prediction {:.0f} integration {:.0f} total {:.0f}", + logger.Info("Per-image mean processing time (microseconds): compression {:.0f} preprocess {:.0f} azint {:.0f} spot finding {:.0f} indexing {:.0f} refinement {:.0f} indexing analysis {:.0f} prediction {:.0f} integration {:.0f} total {:.0f}", image_mean_time.compression * 1e6, image_mean_time.preprocessing * 1e6, image_mean_time.azint * 1e6, image_mean_time.spot_finding * 1e6, image_mean_time.indexing * 1e6, image_mean_time.refinement * 1e6, + image_mean_time.indexing_analysis * 1e6, image_mean_time.bragg_prediction * 1e6, image_mean_time.integration * 1e6, image_mean_time.processing * 1e6); diff --git a/common/JFJochMessages.h b/common/JFJochMessages.h index 191506ab..2d86ef58 100644 --- a/common/JFJochMessages.h +++ b/common/JFJochMessages.h @@ -94,6 +94,7 @@ struct DataMessage { std::optional integration_time_s; std::optional preprocessing_time_s; std::optional compression_time_s; + std::optional index_analysis_time_s; std::vector spots; std::optional spot_count; diff --git a/docs/CBOR.md b/docs/CBOR.md index 57f0d64e..fb84aa11 100644 --- a/docs/CBOR.md +++ b/docs/CBOR.md @@ -167,6 +167,7 @@ See [DECTRIS documentation](https://github.com/dectris/documentation/tree/main/s | spot_finding_time | float | Time spent on spot finding \[s\] | | | | indexing_time | float | Time spent on indexing \[s\] | | | | refinement_time | float | Time spent on refinement of indexing solution and experimental geometry \[s\] | | | +| index_analysis_time | float | Time spent on analyzing idnexing solution, calculating profile radius and mosaicity \[s\] | | | | bragg_prediction_time | float | Time spent on predicting Bragg spots \[s\] | | | | integration_time | float | Time spent on Bragg integration \[s\] | | | | processing_time | float | Total processing time \[s\] | | | diff --git a/frame_serialize/CBORStream2Deserializer.cpp b/frame_serialize/CBORStream2Deserializer.cpp index 5166fb0e..6958274a 100644 --- a/frame_serialize/CBORStream2Deserializer.cpp +++ b/frame_serialize/CBORStream2Deserializer.cpp @@ -685,6 +685,8 @@ namespace { message.bragg_prediction_time_s = GetCBORFloat(value); else if (key == "refinement_time") message.refinement_time_s = GetCBORFloat(value); + else if (key == "index_analysis_time") + message.index_analysis_time_s = GetCBORFloat(value); else if (key == "processing_time") message.processing_time_s = GetCBORFloat(value); else if (key == "preprocessing_time") diff --git a/frame_serialize/CBORStream2Serializer.cpp b/frame_serialize/CBORStream2Serializer.cpp index faf294f6..60cca90c 100644 --- a/frame_serialize/CBORStream2Serializer.cpp +++ b/frame_serialize/CBORStream2Serializer.cpp @@ -711,6 +711,7 @@ void CBORStream2Serializer::SerializeImageInternal(CborEncoder &mapEncoder, cons CBOR_ENC(mapEncoder, "integration_time", message.integration_time_s); CBOR_ENC(mapEncoder, "refinement_time", message.refinement_time_s); CBOR_ENC(mapEncoder, "preprocessing_time", message.preprocessing_time_s); + CBOR_ENC(mapEncoder, "index_analysis_time", message.index_analysis_time_s); CBOR_ENC(mapEncoder, "indexing_unit_cell", message.indexing_unit_cell); CBOR_ENC(mapEncoder, "xfel_pulse_id", message.xfel_pulse_id); CBOR_ENC(mapEncoder, "xfel_event_code", message.xfel_event_code); diff --git a/image_analysis/indexing/AnalyzeIndexing.cpp b/image_analysis/indexing/AnalyzeIndexing.cpp index fab95eb6..02181045 100644 --- a/image_analysis/indexing/AnalyzeIndexing.cpp +++ b/image_analysis/indexing/AnalyzeIndexing.cpp @@ -277,6 +277,8 @@ namespace { bool AnalyzeIndexing(DataMessage &message, const DiffractionExperiment &experiment, const CrystalLattice &latt) { + auto start_time = std::chrono::steady_clock::now(); + std::vector indexed_spots(message.spots.size()); // Check spots @@ -327,25 +329,26 @@ bool AnalyzeIndexing(DataMessage &message, nspots_ref++; } + bool outcome = false; if (nspots_indexed >= viable_cell_min_spots && nspots_indexed >= std::lround(min_percentage_spots * nspots_ref)) { auto uc = latt.GetUnitCell(); - if (!ok(uc.a) || !ok(uc.b) || !ok(uc.c) || !ok(uc.alpha) || !ok(uc.beta) || !ok(uc.gamma)) - return false; + if (ok(uc.a) && ok(uc.b) && ok(uc.c) && ok(uc.alpha) && ok(uc.beta) && ok(uc.gamma)) { + message.indexing_result = true; + assert(indexed_spots.size() == message.spots.size()); + for (int i = 0; i < message.spots.size(); i++) + message.spots[i].indexed = indexed_spots[i]; - message.indexing_result = true; - assert(indexed_spots.size() == message.spots.size()); - for (int i = 0; i < message.spots.size(); i++) - message.spots[i].indexed = indexed_spots[i]; - - message.profile_radius = FitProfileRadius(message.spots); - message.spot_count_indexed = nspots_indexed; - message.indexing_lattice = latt; - message.indexing_unit_cell = latt.GetUnitCell(); - message.mosaicity_deg = CalcMosaicityXDS(experiment, message.spots, astar, bstar, cstar); - - return true; + message.profile_radius = FitProfileRadius(message.spots); + message.spot_count_indexed = nspots_indexed; + message.indexing_lattice = latt; + message.indexing_unit_cell = latt.GetUnitCell(); + message.mosaicity_deg = CalcMosaicityXDS(experiment, message.spots, astar, bstar, cstar); + outcome = true; + } } - message.indexing_result = false; - return false; + auto end_time = std::chrono::steady_clock::now(); + message.index_analysis_time_s = std::chrono::duration(end_time - start_time).count(); + message.indexing_result = outcome; + return outcome; } diff --git a/receiver/JFJochReceiverPlots.cpp b/receiver/JFJochReceiverPlots.cpp index ac0fe2f5..e7adac9f 100644 --- a/receiver/JFJochReceiverPlots.cpp +++ b/receiver/JFJochReceiverPlots.cpp @@ -115,6 +115,7 @@ void JFJochReceiverPlots::Setup(const DiffractionExperiment &experiment, const A preprocessing_time.Clear(r); compression_time.Clear(r); azint_time.Clear(r); + indexing_analysis_time.Clear(r); } void JFJochReceiverPlots::Add(const DataMessage &msg, const AzimuthalIntegrationProfile &profile) { @@ -146,6 +147,7 @@ void JFJochReceiverPlots::Add(const DataMessage &msg, const AzimuthalIntegration preprocessing_time.AddElement(msg.number, msg.preprocessing_time_s); compression_time.AddElement(msg.number, msg.compression_time_s); azint_time.AddElement(msg.number, msg.azint_time_s); + indexing_analysis_time.AddElement(msg.number, msg.index_analysis_time_s); if (msg.indexing_unit_cell) { indexing_uc_a.AddElement(msg.number, msg.indexing_unit_cell->a); @@ -361,6 +363,11 @@ MultiLinePlot JFJochReceiverPlots::GetPlots(const PlotRequest &request) { if (!indexing.x.empty()) ret.AddPlot(indexing); + auto indexing_analysis = indexing_analysis_time.GetMeanPerBin(nbins, start, incr, request.fill_value); + indexing_analysis.title = "indexing analysis"; + if (!indexing_analysis.x.empty()) + ret.AddPlot(indexing_analysis); + auto integration = integration_time.GetMeanPerBin(nbins, start, incr, request.fill_value); integration.title = "integration"; if (!integration.x.empty()) @@ -437,6 +444,7 @@ MeanProcessingTime JFJochReceiverPlots::GetMeanProcessingTime() const { ret.processing = total_processing_time.Mean(); ret.preprocessing = preprocessing_time.Mean(); ret.azint = azint_time.Mean(); + ret.indexing_analysis = indexing_analysis_time.Mean(); return ret; } diff --git a/receiver/JFJochReceiverPlots.h b/receiver/JFJochReceiverPlots.h index e725d1c7..0094c1af 100644 --- a/receiver/JFJochReceiverPlots.h +++ b/receiver/JFJochReceiverPlots.h @@ -28,6 +28,7 @@ struct MeanProcessingTime { float integration; float bragg_prediction; float processing; + float indexing_analysis; }; class JFJochReceiverPlots { @@ -97,6 +98,7 @@ class JFJochReceiverPlots { StatusVector preprocessing_time; StatusVector compression_time; StatusVector azint_time; + StatusVector indexing_analysis_time; MultiLinePlot GetROIPlot(PlotType type, int64_t nbins, float start, float incr, const std::optional &fill_value) const; diff --git a/writer/CMakeLists.txt b/writer/CMakeLists.txt index 9237fbfe..938feacb 100644 --- a/writer/CMakeLists.txt +++ b/writer/CMakeLists.txt @@ -31,6 +31,8 @@ ADD_LIBRARY(JFJochWriter STATIC TARGET_LINK_LIBRARIES(JFJochWriter JFJochPreview JFJochImagePuller JFJochLogger JFJochHDF5Wrappers CBORStream2FrameSerialize) -ADD_EXECUTABLE(jfjoch_writer jfjoch_writer.cpp) +ADD_EXECUTABLE(jfjoch_writer jfjoch_writer.cpp + HDF5DataFilePluginPerformance.cpp + HDF5DataFilePluginPerformance.h) TARGET_LINK_LIBRARIES(jfjoch_writer JFJochWriter) INSTALL(TARGETS jfjoch_writer RUNTIME COMPONENT writer) diff --git a/writer/HDF5DataFile.cpp b/writer/HDF5DataFile.cpp index 85a727b4..07486f4f 100644 --- a/writer/HDF5DataFile.cpp +++ b/writer/HDF5DataFile.cpp @@ -13,10 +13,11 @@ #include "HDF5DataFilePluginXFEL.h" #include "HDF5DataFilePluginDetector.h" #include "HDF5DataFilePluginROI.h" -#include "../include/spdlog/fmt/fmt.h" -#include "HDF5NXmx.h" +#include "HDF5DataFilePluginPerformance.h" #include "HDF5DataFilePluginImageStats.h" #include "HDF5DataFilePluginReflection.h" +#include "../include/spdlog/fmt/fmt.h" +#include "HDF5NXmx.h" #include "../common/time_utc.h" HDF5DataFile::HDF5DataFile(const StartMessage &msg, uint64_t in_file_number) { @@ -52,6 +53,7 @@ HDF5DataFile::HDF5DataFile(const StartMessage &msg, uint64_t in_file_number) { plugins.emplace_back(std::make_unique(msg)); plugins.emplace_back(std::make_unique()); plugins.emplace_back(std::make_unique()); + plugins.emplace_back(std::make_unique()); } std::optional HDF5DataFile::Close() { diff --git a/writer/HDF5DataFilePluginMX.cpp b/writer/HDF5DataFilePluginMX.cpp index f9c7cb5d..224cc72b 100644 --- a/writer/HDF5DataFilePluginMX.cpp +++ b/writer/HDF5DataFilePluginMX.cpp @@ -93,16 +93,6 @@ void HDF5DataFilePluginMX::OpenFile(HDF5File &data_file, const DataMessage &msg, spot_count_ice.reserve(images_per_file); spot_count_indexed.reserve(images_per_file); spot_count_low_res.reserve(images_per_file); - - indexing_time.reserve(images_per_file); - spot_finding_time.reserve(images_per_file); - integration_time.reserve(images_per_file); - refinement_time.reserve(images_per_file); - processing_time.reserve(images_per_file); - bragg_prediction_time.reserve(images_per_file); - preprocessing_time.reserve(images_per_file); - compression_time.reserve(images_per_file); - azint_time.reserve(images_per_file); } void HDF5DataFilePluginMX::Write(const DataMessage &msg, uint64_t image_number) { @@ -152,16 +142,6 @@ void HDF5DataFilePluginMX::Write(const DataMessage &msg, uint64_t image_number) spot_count_ice[image_number] = msg.spot_count_ice_rings.value_or(0); spot_count_low_res[image_number] = msg.spot_count_low_res.value_or(0); - indexing_time[image_number] = msg.indexing_time_s.value_or(NAN); - spot_finding_time[image_number] = msg.spot_finding_time_s.value_or(NAN); - integration_time[image_number] = msg.integration_time_s.value_or(NAN); - refinement_time[image_number] = msg.refinement_time_s.value_or(NAN); - processing_time[image_number] = msg.processing_time_s.value_or(NAN); - bragg_prediction_time[image_number] = msg.bragg_prediction_time_s.value_or(NAN); - preprocessing_time[image_number] = msg.preprocessing_time_s.value_or(NAN); - compression_time[image_number] = msg.compression_time_s.value_or(NAN); - azint_time[image_number] = msg.azint_time_s.value_or(NAN); - if (indexing) { indexed[image_number] = msg.indexing_result.value_or(0); profile_radius[image_number] = msg.profile_radius.value_or(NAN); @@ -212,25 +192,6 @@ void HDF5DataFilePluginMX::WriteFinal(HDF5File &data_file) { } } - if (!spot_finding_time.empty()) - data_file.SaveVector("/entry/MX/spotFindingTime", spot_finding_time.vec())->Units("s"); - if (!indexing_time.empty()) - data_file.SaveVector("/entry/MX/indexingTime", indexing_time.vec())->Units("s"); - if (!integration_time.empty()) - data_file.SaveVector("/entry/MX/integrationTime", integration_time.vec())->Units("s"); - if (!refinement_time.empty()) - data_file.SaveVector("/entry/MX/refinementTime", refinement_time.vec())->Units("s"); - if (!processing_time.empty()) - data_file.SaveVector("/entry/MX/processingTime", processing_time.vec())->Units("s"); - if (!bragg_prediction_time.empty()) - data_file.SaveVector("/entry/MX/braggPredictionTime", bragg_prediction_time.vec())->Units("s"); - if (!preprocessing_time.empty()) - data_file.SaveVector("/entry/MX/preprocessingTime", preprocessing_time.vec())->Units("s"); - if (!compression_time.empty()) - data_file.SaveVector("/entry/MX/compressionTime", compression_time.vec())->Units("s"); - if (!azint_time.empty()) - data_file.SaveVector("/entry/MX/azIntTime", azint_time.vec())->Units("s"); - if (!strong_pixel_count.empty()) data_file.SaveVector("/entry/MX/strongPixels", strong_pixel_count.vec()); diff --git a/writer/HDF5DataFilePluginMX.h b/writer/HDF5DataFilePluginMX.h index ecd9ac6f..8cb64189 100644 --- a/writer/HDF5DataFilePluginMX.h +++ b/writer/HDF5DataFilePluginMX.h @@ -50,15 +50,7 @@ class HDF5DataFilePluginMX : public HDF5DataFilePlugin { AutoIncrVector niggli_class; AutoIncrVector bravais_lattice; - AutoIncrVector spot_finding_time{NAN}; - AutoIncrVector indexing_time{NAN}; - AutoIncrVector refinement_time{NAN}; - AutoIncrVector integration_time{NAN}; - AutoIncrVector processing_time{NAN}; - AutoIncrVector bragg_prediction_time{NAN}; - AutoIncrVector preprocessing_time{NAN}; - AutoIncrVector compression_time{NAN}; - AutoIncrVector azint_time{NAN}; + public: explicit HDF5DataFilePluginMX(const StartMessage& msg); void OpenFile(HDF5File &data_file, const DataMessage& msg, size_t images_per_file) override; diff --git a/writer/HDF5DataFilePluginPerformance.cpp b/writer/HDF5DataFilePluginPerformance.cpp new file mode 100644 index 00000000..d548162f --- /dev/null +++ b/writer/HDF5DataFilePluginPerformance.cpp @@ -0,0 +1,54 @@ +// SPDX-FileCopyrightText: 2024 Filip Leonarski, Paul Scherrer Institute +// SPDX-License-Identifier: GPL-3.0-only + +#include "HDF5DataFilePluginPerformance.h" + +void HDF5DataFilePluginPerformance::OpenFile(HDF5File &data_file, const DataMessage &msg, size_t images_per_file) { + indexing_time.reserve(images_per_file); + index_analysis_time.reserve(images_per_file); + spot_finding_time.reserve(images_per_file); + integration_time.reserve(images_per_file); + refinement_time.reserve(images_per_file); + processing_time.reserve(images_per_file); + bragg_prediction_time.reserve(images_per_file); + preprocessing_time.reserve(images_per_file); + compression_time.reserve(images_per_file); + azint_time.reserve(images_per_file); +} + +void HDF5DataFilePluginPerformance::Write(const DataMessage &msg, uint64_t image_number) { + indexing_time[image_number] = msg.indexing_time_s.value_or(NAN); + spot_finding_time[image_number] = msg.spot_finding_time_s.value_or(NAN); + integration_time[image_number] = msg.integration_time_s.value_or(NAN); + refinement_time[image_number] = msg.refinement_time_s.value_or(NAN); + processing_time[image_number] = msg.processing_time_s.value_or(NAN); + bragg_prediction_time[image_number] = msg.bragg_prediction_time_s.value_or(NAN); + preprocessing_time[image_number] = msg.preprocessing_time_s.value_or(NAN); + compression_time[image_number] = msg.compression_time_s.value_or(NAN); + azint_time[image_number] = msg.azint_time_s.value_or(NAN); +} + +void HDF5DataFilePluginPerformance::WriteFinal(HDF5File &data_file) { + HDF5Group(data_file, "/entry/profiling").NXClass("NXcollection"); + + if (!spot_finding_time.empty()) + data_file.SaveVector("/entry/profiling/spotFindingTime", spot_finding_time.vec())->Units("s"); + if (!indexing_time.empty()) + data_file.SaveVector("/entry/profiling/indexingTime", indexing_time.vec())->Units("s"); + if (!integration_time.empty()) + data_file.SaveVector("/entry/profiling/integrationTime", integration_time.vec())->Units("s"); + if (!refinement_time.empty()) + data_file.SaveVector("/entry/profiling/refinementTime", refinement_time.vec())->Units("s"); + if (!processing_time.empty()) + data_file.SaveVector("/entry/profiling/processingTime", processing_time.vec())->Units("s"); + if (!bragg_prediction_time.empty()) + data_file.SaveVector("/entry/profiling/braggPredictionTime", bragg_prediction_time.vec())->Units("s"); + if (!preprocessing_time.empty()) + data_file.SaveVector("/entry/profiling/preprocessingTime", preprocessing_time.vec())->Units("s"); + if (!compression_time.empty()) + data_file.SaveVector("/entry/profiling/compressionTime", compression_time.vec())->Units("s"); + if (!azint_time.empty()) + data_file.SaveVector("/entry/profiling/azIntTime", azint_time.vec())->Units("s"); + if (!index_analysis_time.empty()) + data_file.SaveVector("/entry/profiling/indexAnalysisTime", index_analysis_time.vec())->Units("s"); +} diff --git a/writer/HDF5DataFilePluginPerformance.h b/writer/HDF5DataFilePluginPerformance.h new file mode 100644 index 00000000..e774087e --- /dev/null +++ b/writer/HDF5DataFilePluginPerformance.h @@ -0,0 +1,25 @@ +// SPDX-FileCopyrightText: 2024 Filip Leonarski, Paul Scherrer Institute +// SPDX-License-Identifier: GPL-3.0-only + +#pragma once + +#include "HDF5DataFilePlugin.h" +#include "../common/AutoIncrVector.h" + +class HDF5DataFilePluginPerformance : public HDF5DataFilePlugin { + AutoIncrVector spot_finding_time{NAN}; + AutoIncrVector indexing_time{NAN}; + AutoIncrVector refinement_time{NAN}; + AutoIncrVector integration_time{NAN}; + AutoIncrVector processing_time{NAN}; + AutoIncrVector bragg_prediction_time{NAN}; + AutoIncrVector preprocessing_time{NAN}; + AutoIncrVector compression_time{NAN}; + AutoIncrVector azint_time{NAN}; + AutoIncrVector index_analysis_time{NAN}; + +public: + void OpenFile(HDF5File &data_file, const DataMessage &msg, size_t images_per_file) override; + void Write(const DataMessage &msg, uint64_t image_number) override; + void WriteFinal(HDF5File &data_file) override; +};