aboutsummaryrefslogtreecommitdiff
path: root/libcrystfel
diff options
context:
space:
mode:
authorThomas White <taw@physics.org>2022-04-29 16:53:49 +0200
committerThomas White <taw@physics.org>2022-05-04 14:47:35 +0200
commit3fb81ddf7059599dba9b8b223156801af6885fc1 (patch)
tree23fb95dbf4279c164b5f564082fb4b9b40e5bbf2 /libcrystfel
parentcdb51dbec109ccde45c8a4ceb29ea925d01e2920 (diff)
Add improved profiling
Improvements: - Recursive, so we can see how things are working at different levels - Everything is profiled, even if not explicitly labelled - No possibility of losing time - Detects mistakes if routines aren't wrapped correctly
Diffstat (limited to 'libcrystfel')
-rw-r--r--libcrystfel/CMakeLists.txt2
-rw-r--r--libcrystfel/meson.build1
-rw-r--r--libcrystfel/src/image-hdf5.c11
-rw-r--r--libcrystfel/src/image.c39
-rw-r--r--libcrystfel/src/index.c39
-rw-r--r--libcrystfel/src/profile.c220
-rw-r--r--libcrystfel/src/profile.h42
7 files changed, 344 insertions, 10 deletions
diff --git a/libcrystfel/CMakeLists.txt b/libcrystfel/CMakeLists.txt
index 69668a8c..3ca50b1f 100644
--- a/libcrystfel/CMakeLists.txt
+++ b/libcrystfel/CMakeLists.txt
@@ -62,6 +62,7 @@ set(LIBCRYSTFEL_SOURCES
src/image-hdf5.c
src/fom.c
src/image-msgpack.c
+ src/profile.c
${BISON_symopp_OUTPUTS}
${FLEX_symopl_OUTPUTS}
src/indexers/dirax.c
@@ -99,6 +100,7 @@ set(LIBCRYSTFEL_HEADERS
src/colscale.h
src/detgeom.h
src/fom.h
+ src/profile.h
)
add_library(${PROJECT_NAME} SHARED
diff --git a/libcrystfel/meson.build b/libcrystfel/meson.build
index 5b10ce14..d333d554 100644
--- a/libcrystfel/meson.build
+++ b/libcrystfel/meson.build
@@ -121,6 +121,7 @@ libcrystfel_sources = ['src/image.c',
'src/colscale.c',
'src/detgeom.c',
'src/fom.c',
+ 'src/profile.c',
'src/image-cbf.c',
'src/image-hdf5.c',
'src/image-msgpack.c',
diff --git a/libcrystfel/src/image-hdf5.c b/libcrystfel/src/image-hdf5.c
index fd16ac08..529420fb 100644
--- a/libcrystfel/src/image-hdf5.c
+++ b/libcrystfel/src/image-hdf5.c
@@ -42,6 +42,7 @@
#include "image.h"
#include "utils.h"
#include "detgeom.h"
+#include "profile.h"
#include "datatemplate.h"
#include "datatemplate_priv.h"
@@ -395,13 +396,16 @@ static int load_hdf5_hyperslab(struct panel_template *p,
return 1;
}
+ profile_start("H5Dopen2");
dh = H5Dopen2(fh, panel_full_path, H5P_DEFAULT);
if ( dh < 0 ) {
ERROR("Cannot open data for panel %s (%s)\n",
p->name, panel_full_path);
+ profile_end("H5Dopen2");
free(panel_full_path);
return 1;
}
+ profile_end("H5Dopen2");
free(panel_full_path);
@@ -509,7 +513,9 @@ static int load_hdf5_hyperslab(struct panel_template *p,
return 1;
}
+ profile_start("H5Dread");
r = H5Dread(dh, el_type, memspace, dataspace, H5P_DEFAULT, data);
+ profile_end("H5Dread");
if ( r < 0 ) {
ERROR("Couldn't read data for panel %s\n",
p->name);
@@ -592,13 +598,16 @@ int image_hdf5_read(struct image *image,
/* Set all pointers to NULL for easier clean-up */
for ( i=0; i<dtempl->n_panels; i++ ) image->dp[i] = NULL;
+ profile_start("open-hdf5");
fh = open_hdf5(image);
+ profile_end("open-hdf5");
if ( fh < 0 ) {
ERROR("Failed to open file\n");
return 1;
}
for ( i=0; i<dtempl->n_panels; i++ ) {
+ profile_start("load-hdf5-hyperslab");
if ( load_hdf5_hyperslab(&dtempl->panels[i], fh,
image->ev, (void *)&image->dp[i],
H5T_NATIVE_FLOAT,
@@ -606,9 +615,11 @@ int image_hdf5_read(struct image *image,
dtempl->panels[i].data) )
{
ERROR("Failed to load panel data\n");
+ profile_end("load-hdf5-hyperslab");
close_hdf5(fh);
return 1;
}
+ profile_end("load-hdf5-hyperslab");
}
close_hdf5(fh);
diff --git a/libcrystfel/src/image.c b/libcrystfel/src/image.c
index 7ad8d428..2209ffee 100644
--- a/libcrystfel/src/image.c
+++ b/libcrystfel/src/image.c
@@ -42,6 +42,7 @@
#include "image-hdf5.h"
#include "image-cbf.h"
#include "image-msgpack.h"
+#include "profile.h"
#include "datatemplate.h"
#include "datatemplate_priv.h"
@@ -1289,28 +1290,54 @@ static int do_image_read(struct image *image, const DataTemplate *dtempl,
int no_image_data, int no_mask_data)
{
int i;
+ int r;
/* Load the image data */
if ( !no_image_data ) {
- if ( image_read_image_data(image, dtempl) ) return 1;
+ int r;
+ profile_start("load-image-data");
+ r = image_read_image_data(image, dtempl);
+ profile_end("load-image-data");
+ if ( r ) return r;
} else {
- if ( image_set_zero_data(image, dtempl) ) return 1;
+ int r;
+ profile_start("set-zero-image-data");
+ r = image_set_zero_data(image, dtempl);
+ profile_end("set-zero-image-data");
+ if ( r ) return 1;
}
- if ( set_image_parameters(image, dtempl) ) {
+ profile_start("set-image-parameters");
+ r = set_image_parameters(image, dtempl);
+ profile_end("set-image-parameters");
+ if ( r ) {
ERROR("Failed to read image parameters\n");
return 1;
}
- if ( create_detgeom(image, dtempl) ) {
+
+ profile_start("create-detgeom");
+ r = create_detgeom(image, dtempl);
+ profile_end("create-detgeom");
+ if ( r ) {
ERROR("Failed to read geometry information\n");
return 1;
}
- if ( create_badmap(image, dtempl, no_mask_data) ) return 1;
- if ( create_satmap(image, dtempl) ) return 1;
+ profile_start("create-badmap");
+ r = create_badmap(image, dtempl, no_mask_data);
+ profile_end("create-badmap");
+ if ( r ) return 1;
+
+ profile_start("create-satmap");
+ r = create_satmap(image, dtempl);
+ profile_end("create-satmap");
+ if ( r ) return 1;
+
+ profile_start("read-headers-to-cache");
for ( i=0; i<dtempl->n_headers_to_copy; i++ ) {
read_header_to_cache(image, dtempl->headers_to_copy[i]);
}
+ profile_end("read-headers-to-cache");
return 0;
}
diff --git a/libcrystfel/src/index.c b/libcrystfel/src/index.c
index e7b8b8cf..da560dab 100644
--- a/libcrystfel/src/index.c
+++ b/libcrystfel/src/index.c
@@ -49,6 +49,7 @@
#include "geometry.h"
#include "cell-utils.h"
#include "predict-refine.h"
+#include "profile.h"
#include "indexers/dirax.h"
#include "indexers/asdf.h"
#include "indexers/mosflm.h"
@@ -604,47 +605,65 @@ static int try_indexer(struct image *image, IndexingMethod indm,
case INDEXING_DIRAX :
set_last_task(last_task, "indexing:dirax");
+ profile_start("dirax");
r = run_dirax(image, mpriv);
+ profile_end("dirax");
break;
case INDEXING_ASDF :
set_last_task(last_task, "indexing:asdf");
+ profile_start("asdf");
r = run_asdf(image, mpriv);
+ profile_end("asdf");
break;
case INDEXING_MOSFLM :
set_last_task(last_task, "indexing:mosflm");
+ profile_start("mosflm");
r = run_mosflm(image, mpriv);
+ profile_end("mosflm");
break;
case INDEXING_XDS :
set_last_task(last_task, "indexing:xds");
+ profile_start("xds");
r = run_xds(image, mpriv);
+ profile_end("xds");
break;
case INDEXING_FILE :
set_last_task(last_task, "indexing:file");
+ profile_start("fromfile");
r = fromfile_index(image, mpriv);
+ profile_end("fromfile");
break;
case INDEXING_FELIX :
set_last_task(last_task, "indexing:felix");
+ profile_start("felix");
r = felix_index(image, mpriv);
+ profile_end("felix");
break;
case INDEXING_TAKETWO :
set_last_task(last_task, "indexing:taketwo");
+ profile_start("taketwo");
r = taketwo_index(image, mpriv);
+ profile_end("taketwo");
break;
case INDEXING_PINKINDEXER :
set_last_task(last_task, "indexing:pinkindexer");
+ profile_start("pinkindexer");
r = run_pinkIndexer(image, mpriv, ipriv->n_threads);
+ profile_end("pinkindexer");
break;
case INDEXING_XGANDALF :
set_last_task(last_task, "indexing:xgandalf");
+ profile_start("xgandalf");
r = run_xgandalf(image, mpriv);
+ profile_end("xgandalf");
break;
default :
@@ -670,6 +689,7 @@ static int try_indexer(struct image *image, IndexingMethod indm,
for ( i=0; i<r; i++ ) {
int j;
+ int r;
int this_crystal = image->n_crystals - i - 1;
/* ... starting at the end of the (complete) list ... */
@@ -680,9 +700,11 @@ static int try_indexer(struct image *image, IndexingMethod indm,
crystal_set_mosaicity(cr, 0.0);
/* Pre-refinement unit cell check if requested */
- if ( check_cell(ipriv->flags, cr, ipriv->target_cell,
- ipriv->tolerance) )
- {
+ profile_start("prerefine-cell-check");
+ r = check_cell(ipriv->flags, cr, ipriv->target_cell,
+ ipriv->tolerance);
+ profile_end("prerefine-cell-check");
+ if ( r ) {
crystal_set_user_flag(cr, 1);
continue;
}
@@ -690,20 +712,27 @@ static int try_indexer(struct image *image, IndexingMethod indm,
/* Prediction refinement if requested */
if ( ipriv->flags & INDEXING_REFINE )
{
- if ( refine_prediction(image, cr) ) {
+ int r;
+ profile_start("refine");
+ r = refine_prediction(image, cr);
+ profile_end("refine");
+ if ( r ) {
crystal_set_user_flag(cr, 1);
continue;
}
}
/* After refinement unit cell check if requested */
+ profile_start("postrefine-cell-check");
if ( (ipriv->flags & INDEXING_CHECK_CELL)
&& !compare_cell_parameters(crystal_get_cell(cr), ipriv->target_cell,
ipriv->tolerance) )
{
+ profile_end("postrefine-cell-check");
crystal_set_user_flag(cr, 1);
continue;
}
+ profile_end("postrefine-cell-check");
/* Peak alignment check if requested */
if ( ipriv->flags & INDEXING_CHECK_PEAKS )
@@ -719,6 +748,7 @@ static int try_indexer(struct image *image, IndexingMethod indm,
if ( crystal_get_user_flag(cr) ) continue;
/* Check if cell is too similar to existing ones */
+ profile_start("cell-compare-to-others");
for ( j=0; j<this_crystal; j++ ) {
Crystal *that_cr = image->crystals[j];
@@ -738,6 +768,7 @@ static int try_indexer(struct image *image, IndexingMethod indm,
crystal_set_user_flag(cr, 1);
}
}
+ profile_end("cell-compare-to-others");
}
diff --git a/libcrystfel/src/profile.c b/libcrystfel/src/profile.c
new file mode 100644
index 00000000..2bbebf1f
--- /dev/null
+++ b/libcrystfel/src/profile.c
@@ -0,0 +1,220 @@
+/*
+ * profile.c
+ *
+ * Simple profiling according to wall clock time
+ *
+ * Copyright © 2016-2022 Deutsches Elektronen-Synchrotron DESY,
+ * a research centre of the Helmholtz Association.
+ *
+ * Authors:
+ * 2016-2022 Thomas White <taw@physics.org>
+ *
+ * This file is part of CrystFEL.
+ *
+ * CrystFEL is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * CrystFEL is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with CrystFEL. If not, see <http://www.gnu.org/licenses/>.
+ *
+ */
+
+#include <libcrystfel-config.h>
+
+#include <stdlib.h>
+#include <stdio.h>
+#include <string.h>
+#include <time.h>
+#include <assert.h>
+
+#include "profile.h"
+
+#ifndef CLOCK_MONOTONIC_RAW
+#define CLOCK_MONOTONIC_RAW (CLOCK_MONOTONIC)
+#endif
+
+#define MAX_PROFILE_CHILDREN 32
+
+struct _profile_block
+{
+ char *name;
+
+ time_t start_sec;
+ long start_nsec;
+ double total_time;
+
+ struct _profile_block *parent;
+ struct _profile_block *children[MAX_PROFILE_CHILDREN];
+ int n_children;
+};
+
+
+struct _profiledata
+{
+ struct _profile_block *root;
+ struct _profile_block *current;
+};
+
+
+struct _profiledata *pd = NULL;
+
+
+static struct _profile_block *start_profile_block(const char *name)
+{
+ struct _profile_block *b;
+
+ b = malloc(sizeof(struct _profile_block));
+ if ( b == NULL ) return NULL;
+
+ b->name = strdup(name);
+ if ( b->name == NULL ) {
+ free(b);
+ return NULL;
+ }
+ b->n_children = 0;
+
+#ifdef HAVE_CLOCK_GETTIME
+ struct timespec tp;
+ clock_gettime(CLOCK_MONOTONIC_RAW, &tp);
+ b->start_sec = tp.tv_sec;
+ b->start_nsec = tp.tv_nsec;
+#endif
+
+ return b;
+}
+
+
+static void stop_profile_block(struct _profile_block *b)
+{
+#ifdef HAVE_CLOCK_GETTIME
+ struct timespec tp;
+ clock_gettime(CLOCK_MONOTONIC_RAW, &tp);
+ time_t sec = tp.tv_sec - b->start_sec;
+ long nsec = tp.tv_nsec - b->start_nsec;
+ b->total_time = sec + nsec*1e-9;
+#else
+ b->total_time = 0.0;
+#endif
+}
+
+
+void profile_init()
+{
+ if ( pd != NULL ) {
+ fprintf(stderr, "Attempted to initialise profiling twice!\n");
+ fflush(stderr);
+ abort();
+ }
+
+ if ( pd == NULL ) {
+ pd = malloc(sizeof(struct _profiledata));
+ if ( pd == NULL ) return;
+ }
+
+ pd->root = start_profile_block("root");
+ pd->current = pd->root;
+ pd->root->parent = NULL;
+
+#ifndef HAVE_CLOCK_GETTIME
+ printf("Profiling disabled because clock_gettime is not available\n");
+#endif
+}
+
+
+static void print_profile_block(struct _profile_block *b)
+{
+ int i;
+ printf("(%s %.3f", b->name, b->total_time);
+ for ( i=0; i<b->n_children; i++ ) {
+ printf(" ");
+ print_profile_block(b->children[i]);
+ }
+ printf(")");
+}
+
+
+static void free_profile_block(struct _profile_block *b)
+{
+ int i;
+ for ( i=0; i<b->n_children; i++ ) {
+ free_profile_block(b->children[i]);
+ }
+ free(b->name);
+ free(b);
+}
+
+
+void profile_print_and_reset()
+{
+ if ( pd == NULL ) {
+ fprintf(stderr, "Profiling not initialised yet!\n");
+ fflush(stderr);
+ abort();
+ }
+
+ if ( pd->current != pd->root ) {
+ fprintf(stderr, "Attempted to finalise profiling while not "
+ "on root block (%s)\n", pd->current->name);
+ fflush(stderr);
+ abort();
+ }
+
+ stop_profile_block(pd->root);
+
+ print_profile_block(pd->root);
+ printf("\n");
+
+ free_profile_block(pd->root);
+ pd->root = start_profile_block("root");
+ pd->current = pd->root;
+ pd->root->parent = NULL;
+}
+
+
+void profile_start(const char *name)
+{
+ struct _profile_block *b;
+
+ if ( pd == NULL ) return;
+
+ if ( pd->current->n_children >= MAX_PROFILE_CHILDREN ) {
+ fprintf(stderr, "Too many profile children.\n");
+ fflush(stderr);
+ abort();
+ }
+
+ b = start_profile_block(name);
+ b->parent = pd->current;
+ pd->current->children[pd->current->n_children++] = b;
+ pd->current = b;
+}
+
+
+void profile_end(const char *name)
+{
+ if ( pd == NULL ) return;
+
+ if ( pd->current == NULL ) {
+ fprintf(stderr, "No current profile block!\n");
+ fflush(stderr);
+ abort();
+ }
+
+ if ( strcmp(name, pd->current->name) != 0 ) {
+ fprintf(stderr, "Attempt to close wrong profile block (%s) "
+ "current block is %s\n", name, pd->current->name);
+ fflush(stderr);
+ abort();
+ }
+
+ stop_profile_block(pd->current);
+
+ pd->current = pd->current->parent;
+}
diff --git a/libcrystfel/src/profile.h b/libcrystfel/src/profile.h
new file mode 100644
index 00000000..183528ce
--- /dev/null
+++ b/libcrystfel/src/profile.h
@@ -0,0 +1,42 @@
+/*
+ * profile.h
+ *
+ * Simple profiling according to wall clock time
+ *
+ * Copyright © 2016-2022 Deutsches Elektronen-Synchrotron DESY,
+ * a research centre of the Helmholtz Association.
+ *
+ * Authors:
+ * 2016-2022 Thomas White <taw@physics.org>
+ *
+ * This file is part of CrystFEL.
+ *
+ * CrystFEL is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation, either version 3 of the License, or
+ * (at your option) any later version.
+ *
+ * CrystFEL is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with CrystFEL. If not, see <http://www.gnu.org/licenses/>.
+ *
+ */
+
+#ifndef PROFILE_H
+#define PROFILE_H
+
+/**
+ * \file profile.h
+ * Simple wall-clock profiling
+ */
+
+extern void profile_init();
+extern void profile_print_and_reset();
+extern void profile_start(const char *name);
+extern void profile_end(const char *name);
+
+#endif /* PROFILE_H */