Improve recording of timing for different data analysis steps

This commit is contained in:
2026-03-26 15:19:49 +01:00
parent 2d3c87e41e
commit 0eacee0801
20 changed files with 147 additions and 23 deletions

View File

@@ -871,6 +871,10 @@ PlotType ConvertPlotType(const std::optional<std::string>& input) {
if (input == "max_pixel_value") return PlotType::MaxValue;
if (input == "resolution_estimate") return PlotType::ResolutionEstimate;
if (input == "indexing_time") return PlotType::IndexingTime;
if (input == "refinement_time") return PlotType::RefinementTime;
if (input == "spot_finding_time") return PlotType::SpotFindingTime;
if (input == "integration_time") return PlotType::IntegrationTime;
if (input == "bragg_prediction_time") return PlotType::BraggPredictionTime;
if (input == "pixel_sum") return PlotType::PixelSum;
if (input == "processing_time") return PlotType::ImageProcessingTime;
if (input == "beam_center_x") return PlotType::RefinementBeamX;

View File

@@ -91,7 +91,6 @@ components:
- spot_count_indexed
- spot_count_ice
- indexing_rate
- indexing_time
- indexing_unit_cell_length
- indexing_unit_cell_angle
- profile_radius

File diff suppressed because one or more lines are too long

View File

@@ -86,6 +86,11 @@ struct DataMessage {
std::optional<float> image_collection_efficiency;
std::optional<float> processing_time_s;
std::optional<float> spot_finding_time_s;
std::optional<float> indexing_time_s;
std::optional<float> refinement_time_s;
std::optional<float> bragg_prediction_time_s;
std::optional<float> integration_time_s;
std::vector<SpotToSave> spots;
std::optional<int64_t> spot_count;
@@ -104,7 +109,6 @@ struct DataMessage {
std::optional<UnitCell> indexing_unit_cell;
std::optional<int64_t> spot_count_indexed;
std::optional<float> indexing_time_s;
std::optional<float> profile_radius;
std::optional<float> mosaicity_deg;

View File

@@ -14,8 +14,8 @@ enum class PlotType {
IndexingRate, IndexingUnitCellLength,
IndexingUnitCellAngle, ErrorPixels, SaturatedPixels, ImageCollectionEfficiency, ReceiverDelay, ReceiverFreeSendBuf,
ROISum, ROIMean, ROIMaxCount, ROIPixels, ROIWeightedX, ROIWeightedY, PacketsReceived, MaxValue,
ResolutionEstimate, IndexingTime, ProfileRadius, Mosaicity, BFactor, PixelSum, StrongPixels,
ImageProcessingTime, RefinementBeamX, RefinementBeamY
ResolutionEstimate, ProfileRadius, Mosaicity, BFactor, PixelSum, StrongPixels,
RefinementBeamX, RefinementBeamY, ImageProcessingTime,
};
enum class PlotAzintUnit {

View File

@@ -161,7 +161,11 @@ See [DECTRIS documentation](https://github.com/dectris/documentation/tree/main/s
| profile_radius | float | Profile radius of the image - describes distance of observed reflections from the Ewald sphere \[Angstrom^-1\] | | |
| mosaicity | float | Angular range of spots in image from a rotation scan \[degree\] | | |
| b_factor | float | Estimated B-factor (Angstrom^2) | | |
| 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\] | | |
| 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\] | | |
| xfel_pulse_id | uint64 | Bunch ID (for pulsed source, e.g., SwissFEL) | | X |
| xfel_event_code | uint64 | Event code (for pulsed source, e.g., SwissFEL) | | X |

View File

@@ -6,6 +6,8 @@ This is an UNSTABLE release. The release has significant modifications and bug f
* jfjoch_broker: Use httplib for HTTP server instead of Pistache
* jfjoch_broker: Drop OpenSSL support
* jfjoch_broker: Base work for multi-lattice support in the future
* jfjoch_broker: Improve recording time of data analysis steps
* jfjoch_writer: Save per-image information about data analysis timing
* Update dependencies to more recent versions (spdlog, HDF5, Catch2, httplib)
### 1.0.0-rc.132

View File

@@ -677,6 +677,14 @@ namespace {
message.indexing_lattice = CrystalLattice(tmp);
} else if (key == "indexing_time")
message.indexing_time_s = GetCBORFloat(value);
else if (key == "spot_finding_time")
message.spot_finding_time_s = GetCBORFloat(value);
else if (key == "integration_time")
message.integration_time_s = GetCBORFloat(value);
else if (key == "bragg_prediction_time")
message.bragg_prediction_time_s = GetCBORFloat(value);
else if (key == "refinement_time")
message.refinement_time_s = GetCBORFloat(value);
else if (key == "processing_time")
message.processing_time_s = GetCBORFloat(value);
else if (key == "profile_radius")

View File

@@ -705,6 +705,10 @@ void CBORStream2Serializer::SerializeImageInternal(CborEncoder &mapEncoder, cons
CBOR_ENC(mapEncoder, "b_factor", message.b_factor);
CBOR_ENC(mapEncoder, "indexing_time", message.indexing_time_s);
CBOR_ENC(mapEncoder, "processing_time", message.processing_time_s);
CBOR_ENC(mapEncoder, "spot_finding_time", message.spot_finding_time_s);
CBOR_ENC(mapEncoder, "bragg_prediction_time", message.bragg_prediction_time_s);
CBOR_ENC(mapEncoder, "integration_time", message.integration_time_s);
CBOR_ENC(mapEncoder, "refinement_time", message.refinement_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);

View File

@@ -38,6 +38,9 @@ export enum plot_type {
RESOLUTION_ESTIMATE = 'resolution_estimate',
PIXEL_SUM = 'pixel_sum',
PROCESSING_TIME = 'processing_time',
SPOT_FINDING_TIME = 'spot_finding_time',
REFINEMENT_TIME = 'refinement_time',
INTEGRATION_TIME = 'integration_time',
BEAM_CENTER_X = 'beam_center_x',
BEAM_CENTER_Y = 'beam_center_y',
}

View File

@@ -1002,7 +1002,7 @@ export class DefaultService {
* @throws ApiError
*/
public static getPreviewPlot(
type: 'bkg_estimate' | 'azint' | 'azint_1d' | 'spot_count' | 'spot_count_low_res' | 'spot_count_indexed' | 'spot_count_ice' | 'indexing_rate' | 'indexing_time' | 'indexing_unit_cell_length' | 'indexing_unit_cell_angle' | 'profile_radius' | 'mosaicity' | 'b_factor' | 'error_pixels' | 'saturated_pixels' | 'image_collection_efficiency' | 'receiver_delay' | 'receiver_free_send_buf' | 'strong_pixels' | 'roi_sum' | 'roi_mean' | 'roi_max_count' | 'roi_pixels' | 'roi_weighted_x' | 'roi_weighted_y' | 'packets_received' | 'max_pixel_value' | 'resolution_estimate' | 'pixel_sum' | 'processing_time' | 'beam_center_x' | 'beam_center_y',
type: 'bkg_estimate' | 'azint' | 'azint_1d' | 'spot_count' | 'spot_count_low_res' | 'spot_count_indexed' | 'spot_count_ice' | 'indexing_rate' | 'indexing_time' | 'indexing_unit_cell_length' | 'indexing_unit_cell_angle' | 'profile_radius' | 'mosaicity' | 'b_factor' | 'error_pixels' | 'saturated_pixels' | 'image_collection_efficiency' | 'receiver_delay' | 'receiver_free_send_buf' | 'strong_pixels' | 'roi_sum' | 'roi_mean' | 'roi_max_count' | 'roi_pixels' | 'roi_weighted_x' | 'roi_weighted_y' | 'packets_received' | 'max_pixel_value' | 'resolution_estimate' | 'pixel_sum' | 'processing_time' | 'spot_finding_time' | 'refinement_time' | 'integration_time' | 'beam_center_x' | 'beam_center_y',
binning: number = 1,
fill?: number,
experimentalCoord: boolean = false,
@@ -1035,7 +1035,7 @@ export class DefaultService {
* @throws ApiError
*/
public static getPreviewPlotBin(
type: 'bkg_estimate' | 'azint' | 'azint_1d' | 'spot_count' | 'spot_count_low_res' | 'spot_count_indexed' | 'spot_count_ice' | 'indexing_rate' | 'indexing_time' | 'indexing_unit_cell_length' | 'indexing_unit_cell_angle' | 'profile_radius' | 'mosaicity' | 'b_factor' | 'error_pixels' | 'saturated_pixels' | 'image_collection_efficiency' | 'receiver_delay' | 'receiver_free_send_buf' | 'strong_pixels' | 'roi_sum' | 'roi_mean' | 'roi_max_count' | 'roi_pixels' | 'roi_weighted_x' | 'roi_weighted_y' | 'packets_received' | 'max_pixel_value' | 'resolution_estimate' | 'pixel_sum' | 'processing_time' | 'beam_center_x' | 'beam_center_y',
type: 'bkg_estimate' | 'azint' | 'azint_1d' | 'spot_count' | 'spot_count_low_res' | 'spot_count_indexed' | 'spot_count_ice' | 'indexing_rate' | 'indexing_time' | 'indexing_unit_cell_length' | 'indexing_unit_cell_angle' | 'profile_radius' | 'mosaicity' | 'b_factor' | 'error_pixels' | 'saturated_pixels' | 'image_collection_efficiency' | 'receiver_delay' | 'receiver_free_send_buf' | 'strong_pixels' | 'roi_sum' | 'roi_mean' | 'roi_max_count' | 'roi_pixels' | 'roi_weighted_x' | 'roi_weighted_y' | 'packets_received' | 'max_pixel_value' | 'resolution_estimate' | 'pixel_sum' | 'processing_time' | 'spot_finding_time' | 'refinement_time' | 'integration_time' | 'beam_center_x' | 'beam_center_y',
roi?: string,
): CancelablePromise<Blob> {
return __request(OpenAPI, {

View File

@@ -92,6 +92,8 @@ void IndexAndRefine::RefineGeometryIfNeeded(DataMessage &msg, IndexAndRefine::In
if (!outcome.lattice_candidate)
return;
auto start_time = std::chrono::steady_clock::now();
XtalOptimizerData data{
.geom = outcome.experiment.GetDiffractionGeometry(),
.latt = *outcome.lattice_candidate,
@@ -133,6 +135,9 @@ void IndexAndRefine::RefineGeometryIfNeeded(DataMessage &msg, IndexAndRefine::In
msg.beam_corr_x = data.beam_corr_x;
msg.beam_corr_y = data.beam_corr_y;
}
auto end_time = std::chrono::steady_clock::now();
msg.refinement_time_s = std::chrono::duration_cast<std::chrono::duration<double>>(end_time - start_time).count();
}
void IndexAndRefine::QuickPredictAndIntegrate(DataMessage &msg,
@@ -184,7 +189,12 @@ void IndexAndRefine::QuickPredictAndIntegrate(DataMessage &msg,
.mosaicity_deg = std::fabs(mos_deg)
};
auto pred_start_time = std::chrono::steady_clock::now();
auto nrefl = prediction.Calc(outcome.experiment, latt, settings_prediction);
auto pred_end_time = std::chrono::steady_clock::now();
msg.bragg_prediction_time_s = std::chrono::duration<float>(pred_end_time - pred_start_time).count();
auto integration_start_time = std::chrono::steady_clock::now();
auto refl_ret = BraggIntegrate2D(outcome.experiment, image, prediction.GetReflections(), nrefl, msg.number);
constexpr size_t kMaxReflections = 10000;
@@ -212,6 +222,9 @@ void IndexAndRefine::QuickPredictAndIntegrate(DataMessage &msg,
CalcISigma(msg);
CalcWilsonBFactor(msg);
auto integration_end_time = std::chrono::steady_clock::now();
msg.integration_time_s = std::chrono::duration<float>(integration_end_time - integration_start_time).count();
}
void IndexAndRefine::ProcessImage(DataMessage &msg,

View File

@@ -37,9 +37,14 @@ void MXAnalysisAfterFPGA::ReadFromFPGA(const DeviceOutput *output, const SpotFin
if (state == State::Disabled || !find_spots || !settings.enable) {
state = State::Disabled;
} else {
const auto t0 = std::chrono::steady_clock::now();
StrongPixelSet strong_pixel_set;
strong_pixel_set.ReadFPGAOutput(experiment, *output);
strong_pixel_set.FindSpots(experiment, settings, spots, module_number);
const auto t1 = std::chrono::steady_clock::now();
spot_finding_time_total += (t1 - t0);
spot_finding_timing_active = true;
state = State::Enabled;
}
}
@@ -97,6 +102,15 @@ void MXAnalysisAfterFPGA::Process(DataMessage &message, const SpotFindingSetting
if (spot_finding_settings.indexing)
indexer.ProcessImage(message, spot_finding_settings, message.image, *prediction);
}
if (spot_finding_timing_active) {
// total spot-finding time for the whole image
message.spot_finding_time_s = spot_finding_time_total.count() / 1e6;
// report/store ms here
spot_finding_time_total = std::chrono::duration<double, std::micro>{0.0};
spot_finding_timing_active = false;
}
spots.clear();
state = State::Idle;
}

View File

@@ -26,6 +26,9 @@ class MXAnalysisAfterFPGA {
std::vector<uint32_t> arr_strong_pixel;
enum class State {Idle, Disabled, Enabled} state = State::Idle;
std::chrono::duration<double, std::micro> spot_finding_time_total{0.0};
bool spot_finding_timing_active = false;
public:
MXAnalysisAfterFPGA(const DiffractionExperiment& experiment, IndexAndRefine &indexer);

View File

@@ -158,9 +158,11 @@ void MXAnalysisWithoutFPGA::Analyze(DataMessage &output,
|| mask_low_res != settings.low_resolution_limit)
UpdateMaskResolution(settings);
const auto spot_finding_start_time = std::chrono::steady_clock::now();
const std::vector<DiffractionSpot> spots = spotFinder->Run(settings, mask_resolution);
SpotAnalyze(experiment, settings, spots, output);
const auto spot_finding_end_time = std::chrono::steady_clock::now();
output.spot_finding_time_s = std::chrono::duration<float>(spot_finding_end_time - spot_finding_start_time).count();
if (settings.indexing)
indexer.ProcessImage(output, settings,

View File

@@ -14,10 +14,10 @@ void Indexer::Setup(const DiffractionExperiment& experiment) {
IndexerResult Indexer::Run(const std::vector<Coord> &coord) {
IndexerResult ret;
auto start = std::chrono::high_resolution_clock::now();
auto start = std::chrono::steady_clock::now();
ret.lattice = RunInternal(coord, coord.size());
auto end = std::chrono::high_resolution_clock::now();
auto end = std::chrono::steady_clock::now();
std::chrono::duration<float> duration = end - start;
ret.indexing_time_s = duration.count();
return ret;

View File

@@ -99,14 +99,19 @@ void JFJochReceiverPlots::Setup(const DiffractionExperiment &experiment, const A
packets_received.Clear(r);
max_value.Clear(r);
resolution_estimate.Clear(r);
indexing_time.Clear(r);
profile_radius.Clear(r);
mosaicity_deg.Clear(r);
b_factor.Clear(r);
processing_time.Clear(r);
beam_center_x.Clear(r);
beam_center_y.Clear(r);
pixel_sum.Clear(r);
refinement_time.Clear(r);
spot_finding_time.Clear(r);
integration_time.Clear(r);
processing_time.Clear(r);
indexing_time.Clear(r);
bragg_prediction_time.Clear(r);
}
void JFJochReceiverPlots::Add(const DataMessage &msg, const AzimuthalIntegrationProfile &profile) {
@@ -131,6 +136,10 @@ void JFJochReceiverPlots::Add(const DataMessage &msg, const AzimuthalIntegration
max_value.AddElement(msg.number, msg.max_viable_pixel_value);
indexing_time.AddElement(msg.number, msg.indexing_time_s);
processing_time.AddElement(msg.number, msg.processing_time_s);
spot_finding_time.AddElement(msg.number, msg.spot_finding_time_s);
integration_time.AddElement(msg.number, msg.integration_time_s);
refinement_time.AddElement(msg.number, msg.refinement_time_s);
bragg_prediction_time.AddElement(msg.number, msg.bragg_prediction_time_s);
if (msg.indexing_unit_cell) {
indexing_uc_a.AddElement(msg.number, msg.indexing_unit_cell->a);
@@ -253,9 +262,6 @@ MultiLinePlot JFJochReceiverPlots::GetPlots(const PlotRequest &request) {
case PlotType::SaturatedPixels:
ret = saturated_pixels.GetMeanPlot(nbins, start, incr, request.fill_value);
break;
case PlotType::IndexingTime:
ret = indexing_time.GetMeanPlot(nbins, start, incr, request.fill_value);
break;
case PlotType::ProfileRadius:
ret = profile_radius.GetMeanPlot(nbins, start, incr, request.fill_value);
break;
@@ -333,9 +339,33 @@ MultiLinePlot JFJochReceiverPlots::GetPlots(const PlotRequest &request) {
case PlotType::PixelSum:
ret = pixel_sum.GetMeanPlot(nbins, start, incr, request.fill_value);
break;
case PlotType::ImageProcessingTime:
ret = processing_time.GetMeanPlot(nbins, start, incr, request.fill_value);
case PlotType::ImageProcessingTime: {
auto spot_finding = spot_finding_time.GetMeanPerBin(nbins, start, incr, request.fill_value);
spot_finding.title = "spot finding";
ret.AddPlot(spot_finding);
auto indexing = indexing_time.GetMeanPerBin(nbins, start, incr, request.fill_value);
indexing.title = "indexing";
ret.AddPlot(indexing);
auto integration = integration_time.GetMeanPerBin(nbins, start, incr, request.fill_value);
integration.title = "integration";
ret.AddPlot(integration);
auto refinement = refinement_time.GetMeanPerBin(nbins, start, incr, request.fill_value);
refinement.title = "refinement";
ret.AddPlot(refinement);
auto bragg_prediction = bragg_prediction_time.GetMeanPerBin(nbins, start, incr, request.fill_value);
bragg_prediction.title = "bragg prediction";
ret.AddPlot(bragg_prediction);
auto total = processing_time.GetMeanPerBin(nbins, start, incr, request.fill_value);
total.title = "total";
ret.AddPlot(total);
break;
}
case PlotType::RefinementBeamX:
ret = beam_center_x.GetMeanPlot(nbins, start, incr, request.fill_value);
break;
@@ -428,9 +458,6 @@ void JFJochReceiverPlots::GetPlotRaw(std::vector<float> &v, PlotType type, const
case PlotType::SaturatedPixels:
v = saturated_pixels.ExportArray();
break;
case PlotType::IndexingTime:
v = indexing_time.ExportArray();
break;
case PlotType::ProfileRadius:
v = profile_radius.ExportArray();
break;

View File

@@ -64,7 +64,6 @@ class JFJochReceiverPlots {
mutable std::shared_mutex roi_m;
std::map<std::string, ROIStatus> roi_status;
StatusVector indexing_time;
StatusVector profile_radius;
StatusVector mosaicity_deg;
StatusVector b_factor;
@@ -73,6 +72,11 @@ class JFJochReceiverPlots {
StatusVector beam_center_x;
StatusVector beam_center_y;
StatusVector spot_finding_time;
StatusVector indexing_time;
StatusVector refinement_time;
StatusVector integration_time;
StatusVector bragg_prediction_time;
StatusVector processing_time;
MultiLinePlot GetROIPlot(PlotType type, int64_t nbins, float start, float incr,

View File

@@ -93,6 +93,13 @@ 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);
}
void HDF5DataFilePluginMX::Write(const DataMessage &msg, uint64_t image_number) {
@@ -142,6 +149,13 @@ 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);
if (indexing) {
indexed[image_number] = msg.indexing_result.value_or(0);
profile_radius[image_number] = msg.profile_radius.value_or(NAN);
@@ -192,6 +206,18 @@ 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 (!strong_pixel_count.empty())
data_file.SaveVector("/entry/MX/strongPixels", strong_pixel_count.vec());

View File

@@ -49,6 +49,13 @@ class HDF5DataFilePluginMX : public HDF5DataFilePlugin {
AutoIncrVector<uint32_t> niggli_class;
AutoIncrVector<std::string> bravais_lattice;
AutoIncrVector<float> spot_finding_time;
AutoIncrVector<float> indexing_time;
AutoIncrVector<float> refinement_time;
AutoIncrVector<float> integration_time;
AutoIncrVector<float> processing_time;
AutoIncrVector<float> bragg_prediction_time;
public:
explicit HDF5DataFilePluginMX(const StartMessage& msg);
void OpenFile(HDF5File &data_file, const DataMessage& msg, size_t images_per_file) override;