Merge branch 'better-profiling'

13 files changed, 421 insertions, 449 deletions

diff --git a/libcrystfel/CMakeLists.txt b/libcrystfel/CMakeLists.txt
index 9aca17d8..3ca50b1f 100644
--- a/libcrystfel/CMakeLists.txt
+++ b/libcrystfel/CMakeLists.txt
@@ -62,7 +62,7 @@ set(LIBCRYSTFEL_SOURCES
     src/image-hdf5.c
     src/fom.c
     src/image-msgpack.c
-    src/time-accounts.c
+    src/profile.c
     ${BISON_symopp_OUTPUTS}
     ${FLEX_symopl_OUTPUTS}
     src/indexers/dirax.c
@@ -100,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 780bdb77..b5005aa5 100644
--- a/libcrystfel/meson.build
+++ b/libcrystfel/meson.build
@@ -121,7 +121,7 @@ libcrystfel_sources = ['src/image.c',
                        'src/colscale.c',
                        'src/detgeom.c',
                        'src/fom.c',
-                       'src/time-accounts.c',
+                       'src/profile.c',
                        'src/image-cbf.c',
                        'src/image-hdf5.c',
                        'src/image-msgpack.c',
@@ -180,8 +180,7 @@ install_headers(['src/reflist.h',
                  'src/datatemplate.h',
                  'src/colscale.h',
                  'src/detgeom.h',
-                 'src/fom.h',
-                 'src/time-accounts.h'],
+                 'src/fom.h'],
                 subdir: 'crystfel')
 
 # API documentation (Doxygen)
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 7b86588d..2209ffee 100644
--- a/libcrystfel/src/image.c
+++ b/libcrystfel/src/image.c
@@ -42,7 +42,7 @@
 #include "image-hdf5.h"
 #include "image-cbf.h"
 #include "image-msgpack.h"
-#include "time-accounts.h"
+#include "profile.h"
 
 #include "datatemplate.h"
 #include "datatemplate_priv.h"
@@ -1287,49 +1287,67 @@ struct image *image_create_for_simulation(const DataTemplate *dtempl)
 
 
 static int do_image_read(struct image *image, const DataTemplate *dtempl,
-                         int no_image_data, int no_mask_data,
-                         TimeAccounts *taccs)
+                         int no_image_data, int no_mask_data)
 {
 	int i;
+	int r;
 
 	/* Load the image data */
-	time_accounts_set(taccs, TACC_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;
 	}
 
-	time_accounts_set(taccs, TACC_IMAGE_PARAMS);
-	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;
 	}
-	time_accounts_set(taccs, TACC_CREATE_DETGEOM);
-	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;
 	}
-	time_accounts_set(taccs, TACC_CREATE_BADMAP);
-	if ( create_badmap(image, dtempl, no_mask_data) ) return 1;
-	time_accounts_set(taccs, TACC_CREATE_SATMAP);
-	if ( create_satmap(image, dtempl) ) return 1;
 
-	time_accounts_set(taccs, TACC_CACHE_HEADERS);
+	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;
 }
 
 
-struct image *image_read_with_time_accounting(const DataTemplate *dtempl,
-                                              const char *filename,
-                                              const char *event,
-                                              int no_image_data,
-                                              int no_mask_data,
-                                              TimeAccounts *taccs)
+struct image *image_read(const DataTemplate *dtempl,
+                         const char *filename,
+                         const char *event,
+                         int no_image_data,
+                         int no_mask_data)
 {
 	struct image *image;
 
@@ -1355,7 +1373,7 @@ struct image *image_read_with_time_accounting(const DataTemplate *dtempl,
 
 	image->data_source_type = file_type(image->filename);
 
-	if ( do_image_read(image, dtempl, no_image_data, no_mask_data, taccs) ) {
+	if ( do_image_read(image, dtempl, no_image_data, no_mask_data) ) {
 		image_free(image);
 		return NULL;
 	}
@@ -1364,26 +1382,13 @@ struct image *image_read_with_time_accounting(const DataTemplate *dtempl,
 }
 
 
-struct image *image_read(const DataTemplate *dtempl,
-                         const char *filename,
-                         const char *event,
-                         int no_image_data,
-                         int no_mask_data)
-{
-	return image_read_with_time_accounting(dtempl, filename, event,
-	                                       no_image_data, no_mask_data,
-	                                       NULL);
-}
-
-
 struct image *image_read_data_block(const DataTemplate *dtempl,
                                     void *data_block,
                                     size_t data_block_size,
                                     DataSourceType type,
                                     int serial,
                                     int no_image_data,
-                                    int no_mask_data,
-                                    TimeAccounts *taccs)
+                                    int no_mask_data)
 {
 	struct image *image;
 	char tmp[64];
@@ -1407,7 +1412,7 @@ struct image *image_read_data_block(const DataTemplate *dtempl,
 
 	image->data_source_type = type;
 
-	if ( do_image_read(image, dtempl, no_image_data, no_mask_data, taccs) ) {
+	if ( do_image_read(image, dtempl, no_image_data, no_mask_data) ) {
 		image_free(image);
 		ERROR("Failed to load image\n");
 		return NULL;
diff --git a/libcrystfel/src/image.h b/libcrystfel/src/image.h
index 78fd01cd..3746e115 100644
--- a/libcrystfel/src/image.h
+++ b/libcrystfel/src/image.h
@@ -45,7 +45,6 @@ struct image;
 #include "index.h"
 #include "spectrum.h"
 #include "datatemplate.h"
-#include "time-accounts.h"
 
 /**
  * \file image.h
@@ -221,12 +220,6 @@ extern struct image *image_read(const DataTemplate *dtempl,
                                 const char *event,
                                 int no_image_data,
                                 int no_mask_data);
-extern struct image *image_read_with_time_accounting(const DataTemplate *dtempl,
-                                                     const char *filename,
-                                                     const char *event,
-                                                     int no_image_data,
-                                                     int no_mask_data,
-                                                     TimeAccounts *taccs);
 
 extern struct image *image_create_for_simulation(const DataTemplate *dtempl);
 extern struct image *image_read_data_block(const DataTemplate *dtempl,
@@ -235,8 +228,7 @@ extern struct image *image_read_data_block(const DataTemplate *dtempl,
                                            DataSourceType type,
                                            int serial,
                                            int no_image_data,
-                                           int no_mask_data,
-                                           TimeAccounts *taccs);
+                                           int no_mask_data);
 extern void image_free(struct image *image);
 
 extern int image_read_header_float(struct image *image, const char *from,
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..f20e4b7e
--- /dev/null
+++ b/libcrystfel/src/profile.c
@@ -0,0 +1,241 @@
+/*
+ * 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 <unistd.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 char *format_profile_block(struct _profile_block *b)
+{
+	int i;
+	size_t total_len = 0;
+	char *subbufs[MAX_PROFILE_CHILDREN];
+	char *full_buf;
+
+	total_len = 32 + strlen(b->name);
+	for ( i=0; i<b->n_children; i++ ) {
+		subbufs[i] = format_profile_block(b->children[i]);
+		total_len += 1 + strlen(subbufs[i]);
+	}
+
+	full_buf = malloc(total_len);
+	snprintf(full_buf, 32, "(%s %.3f", b->name, b->total_time);
+	for ( i=0; i<b->n_children; i++ ) {
+		strcat(full_buf, " ");
+		strcat(full_buf, subbufs[i]);
+		free(subbufs[i]);
+	}
+	strcat(full_buf, ")");
+
+	return full_buf;
+}
+
+
+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()
+{
+	char *buf;
+	char *buf2;
+
+	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);
+
+	buf = format_profile_block(pd->root);
+	buf2 = malloc(2+strlen(buf));
+	strcpy(buf2, buf);
+	strcat(buf2, "\n");
+	write(STDOUT_FILENO, buf2, strlen(buf2));
+
+	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 */
diff --git a/libcrystfel/src/time-accounts.c b/libcrystfel/src/time-accounts.c
deleted file mode 100644
index df2ccbb2..00000000
--- a/libcrystfel/src/time-accounts.c
+++ /dev/null
@@ -1,265 +0,0 @@
-/*
- * time-accounts.c
- *
- * Simple profiling according to wall clock time
- *
- * Copyright © 2016-2021 Deutsches Elektronen-Synchrotron DESY,
- *                       a research centre of the Helmholtz Association.
- *
- * Authors:
- *  2016-2018 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 "time-accounts.h"
-
-#define MAX_ACCOUNTS 256
-
-#ifndef CLOCK_MONOTONIC_RAW
-#define CLOCK_MONOTONIC_RAW (CLOCK_MONOTONIC)
-#endif
-
-struct _timeaccounts
-{
-	enum timeaccount accs[MAX_ACCOUNTS];
-	time_t sec[MAX_ACCOUNTS];
-	long nsec[MAX_ACCOUNTS];
-	int n_accs;
-	enum timeaccount cur_acc;
-	time_t cur_sec;
-	long cur_nsec;
-};
-
-
-TimeAccounts *time_accounts_init()
-{
-	TimeAccounts *accs = malloc(sizeof(struct _timeaccounts));
-	if ( accs == NULL ) return NULL;
-
-	accs->n_accs = 0;
-	accs->cur_acc = TACC_NOTHING;
-
-#ifndef HAVE_CLOCK_GETTIME
-	printf("Profiling disabled because clock_gettime is not available\n");
-#endif
-
-	return accs;
-}
-
-
-void time_accounts_free(TimeAccounts *accs)
-{
-	free(accs);
-}
-
-
-static int find_account(TimeAccounts *accs, enum timeaccount acc)
-{
-	int i;
-
-	for ( i=0; i<accs->n_accs; i++ ) {
-		if ( accs->accs[i] == acc ) return i;
-	}
-
-	if ( i == MAX_ACCOUNTS ) {
-		static int warned_toomany = 0;
-		if ( !warned_toomany ) printf("Too many time accounts used!\n");
-		warned_toomany = 1;
-		return MAX_ACCOUNTS;
-	}
-
-	/* This is the first time the account is used */
-	accs->accs[i] = acc;
-	accs->sec[i] = 0;
-	accs->nsec[i] = 0;
-	accs->n_accs++;
-	return i;
-}
-
-
-void time_accounts_reset(TimeAccounts *accs)
-{
-	accs->n_accs = 0;
-	accs->cur_acc = TACC_NOTHING;
-}
-
-
-#ifdef HAVE_CLOCK_GETTIME
-
-void time_accounts_set(TimeAccounts *accs, enum timeaccount new_acc)
-{
-	struct timespec tp;
-
-	if ( accs == NULL ) return;
-
-	clock_gettime(CLOCK_MONOTONIC_RAW, &tp);
-
-	/* Record time used on the previous account */
-	if ( accs->cur_acc != TACC_NOTHING ) {
-		int i = find_account(accs, accs->cur_acc);
-		if ( i == MAX_ACCOUNTS ) {
-			printf("Too many time accounts!\n");
-		} else {
-
-			time_t sec = tp.tv_sec - accs->cur_sec;
-			long nsec = tp.tv_nsec - accs->cur_nsec;
-
-			if ( nsec < 0 ) {
-				sec -= 1;
-				nsec += 1000000000;
-			}
-			accs->sec[i] += sec;
-			accs->nsec[i] += nsec;
-
-			while ( accs->nsec[i] > 1000000000 ) {
-				accs->sec[i] += 1;
-				accs->nsec[i] -= 1000000000;
-			}
-
-		}
-	}
-
-	accs->cur_acc = new_acc;
-	accs->cur_sec = tp.tv_sec;
-	accs->cur_nsec = tp.tv_nsec;
-}
-
-#else
-
-void time_accounts_set(TimeAccounts *accs, enum timeaccount new_acc)
-{
-	if ( accs == NULL ) return;
-
-	/* Record time used on the previous account */
-	if ( accs->cur_acc != TACC_NOTHING ) {
-		int i = find_account(accs, accs->cur_acc);
-		if ( i == MAX_ACCOUNTS ) {
-			printf("Too many time accounts!\n");
-		} else {
-			/* Do nothing because we have no timer */
-		}
-	}
-
-	accs->cur_acc = new_acc;
-	accs->cur_sec = 0;
-	accs->cur_nsec = 0;
-}
-
-#endif
-
-static const char *taccname(enum timeaccount acc)
-{
-	switch ( acc ) {
-		case TACC_NOTHING : return "Nothing";
-		case TACC_SELECT : return "select()";
-		case TACC_STREAMREAD : return "Stream read";
-		case TACC_SIGNALS : return "Checking signals";
-		case TACC_QUEUETOPUP : return "Topping up queue";
-		case TACC_STATUS : return "Printing status";
-		case TACC_ENDCHECK : return "Checking end";
-		case TACC_WAKEUP : return "Waking up workers";
-		case TACC_WAITPID : return "Waiting on workers";
-		case TACC_WAITFILE : return "Waiting for image file";
-		case TACC_IMAGE_DATA : return "Reading image data";
-		case TACC_IMAGE_PARAMS : return "Reading image parameters";
-		case TACC_CREATE_DETGEOM : return "Creating detgeom";
-		case TACC_CREATE_BADMAP : return "Creating bad pixel map";
-		case TACC_CREATE_SATMAP : return "Creating saturation map";
-		case TACC_CACHE_HEADERS : return "Caching image headers";
-		case TACC_FILTER : return "Image filters";
-		case TACC_RESRANGE : return "Resolution range";
-		case TACC_PEAKSEARCH : return "Peak search";
-		case TACC_INDEXING : return "Indexing";
-		case TACC_PREDPARAMS : return "Prediction parameters";
-		case TACC_INTEGRATION : return "Integration";
-		case TACC_TOTALS : return "Crystal totals";
-		case TACC_WRITESTREAM : return "Writing stream";
-		case TACC_CLEANUP : return "Image cleanup";
-		case TACC_EVENTWAIT : return "Waiting for event";
-		case TACC_FINALCLEANUP : return "Final cleanup";
-		default : return "Unknown";
-	}
-}
-
-
-static const char *taccname_short(enum timeaccount acc)
-{
-	switch ( acc ) {
-		case TACC_NOTHING : return "?????";
-		case TACC_SELECT : return "selct";
-		case TACC_STREAMREAD : return "sread";
-		case TACC_SIGNALS : return "signs";
-		case TACC_QUEUETOPUP : return "qfill";
-		case TACC_STATUS : return "print";
-		case TACC_ENDCHECK : return "endch";
-		case TACC_WAKEUP : return "wakew";
-		case TACC_WAITPID : return "waitw";
-		case TACC_WAITFILE : return "wfile";
-		case TACC_IMAGE_DATA : return "idata";
-		case TACC_IMAGE_PARAMS : return "iprms";
-		case TACC_CREATE_DETGEOM : return "dgeom";
-		case TACC_CREATE_BADMAP : return "bdmap";
-		case TACC_CREATE_SATMAP : return "stmap";
-		case TACC_CACHE_HEADERS : return "headc";
-		case TACC_FILTER : return "filtr";
-		case TACC_RESRANGE : return "rrnge";
-		case TACC_PEAKSEARCH : return "peaks";
-		case TACC_INDEXING : return "index";
-		case TACC_PREDPARAMS : return "predp";
-		case TACC_INTEGRATION : return "integ";
-		case TACC_TOTALS : return "ctotl";
-		case TACC_WRITESTREAM : return "swrte";
-		case TACC_CLEANUP : return "clean";
-		case TACC_EVENTWAIT : return "wevnt";
-		case TACC_FINALCLEANUP : return "final";
-		default : return "unkwn";
-	}
-}
-
-
-void time_accounts_print_short(TimeAccounts *accs)
-{
-	int i;
-	time_accounts_set(accs, accs->cur_acc);
-	for ( i=0; i<accs->n_accs; i++ ) {
-		printf("%s: %.3f ", taccname_short(accs->accs[i]),
-		       (double)accs->sec[i] + accs->nsec[i]/1e9);
-	}
-	printf("\n");
-	fflush(stdout);
-}
-
-
-void time_accounts_print(TimeAccounts *accs)
-{
-	int i;
-	printf("Wall clock time budget:\n");
-	printf("-----------------------\n");
-	for ( i=0; i<accs->n_accs; i++ ) {
-		printf("%25s: %10lli sec %10li nsec\n", taccname(accs->accs[i]),
-		       (long long)accs->sec[i], accs->nsec[i]);
-	}
-}
diff --git a/libcrystfel/src/time-accounts.h b/libcrystfel/src/time-accounts.h
deleted file mode 100644
index 56b44fa6..00000000
--- a/libcrystfel/src/time-accounts.h
+++ /dev/null
@@ -1,75 +0,0 @@
-/*
- * time-accounts.h
- *
- * Simple profiling according to wall clock time
- *
- * Copyright © 2016-2021 Deutsches Elektronen-Synchrotron DESY,
- *                       a research centre of the Helmholtz Association.
- *
- * Authors:
- *  2016-2018 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 TIME_ACCOUNTS_H
-#define TIME_ACCOUNTS_H
-
-enum timeaccount
-{
-	TACC_NOTHING,
-	TACC_STREAMREAD,
-	TACC_SELECT,
-	TACC_SIGNALS,
-	TACC_QUEUETOPUP,
-	TACC_STATUS,
-	TACC_ENDCHECK,
-	TACC_WAKEUP,
-	TACC_WAITPID,
-	TACC_WAITFILE,
-	TACC_IMAGE_DATA,
-	TACC_IMAGE_PARAMS,
-	TACC_CREATE_DETGEOM,
-	TACC_CREATE_BADMAP,
-	TACC_CREATE_SATMAP,
-	TACC_CACHE_HEADERS,
-	TACC_FILTER,
-	TACC_RESRANGE,
-	TACC_PEAKSEARCH,
-	TACC_INDEXING,
-	TACC_PREDPARAMS,
-	TACC_INTEGRATION,
-	TACC_TOTALS,
-	TACC_WRITESTREAM,
-	TACC_CLEANUP,
-	TACC_EVENTWAIT,
-	TACC_FINALCLEANUP,
-};
-
-typedef struct _timeaccounts TimeAccounts;
-
-extern TimeAccounts *time_accounts_init(void);
-extern void time_accounts_free(TimeAccounts *accs);
-
-extern void time_accounts_set(TimeAccounts *accs, enum timeaccount new_acc);
-
-extern void time_accounts_reset(TimeAccounts *accs);
-
-extern void time_accounts_print_short(TimeAccounts *accs);
-extern void time_accounts_print(TimeAccounts *accs);
-
-#endif	/* TIME_ACCOUNTS_H */
diff --git a/src/im-sandbox.c b/src/im-sandbox.c
index 501efb45..bd3f47e7 100644
--- a/src/im-sandbox.c
+++ b/src/im-sandbox.c
@@ -60,8 +60,8 @@
 
 #include "im-sandbox.h"
 #include "process_image.h"
-#include "time-accounts.h"
 #include "im-zmq.h"
+#include "profile.h"
 
 
 struct sandbox
@@ -331,6 +331,10 @@ static int run_work(const struct index_args *iargs, Stream *st,
 	int allDone = 0;
 	struct im_zmq *zmqstuff = NULL;
 
+	if ( sb->profile ) {
+		profile_init();
+	}
+
 	/* Connect via ZMQ */
 	if ( sb->zmq ) {
 		zmqstuff = im_zmq_connect(sb->zmq_address,
@@ -345,7 +349,6 @@ static int run_work(const struct index_args *iargs, Stream *st,
 
 	while ( !allDone ) {
 
-		TimeAccounts *taccs;
 		struct pattern_args pargs;
 		int ser;
 		char *line;
@@ -355,16 +358,15 @@ static int run_work(const struct index_args *iargs, Stream *st,
 		char *ser_str = NULL;
 		int ok = 1;
 
-		taccs = time_accounts_init();
-
 		/* Wait until an event is ready */
-		time_accounts_set(taccs, TACC_EVENTWAIT);
 		sb->shared->pings[cookie]++;
 		set_last_task(sb->shared->last_task[cookie], "wait_event");
+		profile_start("wait-queue-semaphore");
 		if ( sem_wait(sb->queue_sem) != 0 ) {
 			ERROR("Failed to wait on queue semaphore: %s\n",
 			      strerror(errno));
 		}
+		profile_end("wait-queue-semaphore");
 
 		/* Get the event from the queue */
 		set_last_task(sb->shared->last_task[cookie], "read_queue");
@@ -451,19 +453,18 @@ static int run_work(const struct index_args *iargs, Stream *st,
 		}
 
 		sb->shared->time_last_start[cookie] = get_monotonic_seconds();
+		profile_start("process-image");
 		process_image(iargs, &pargs, st, cookie, tmpdir, ser,
-		              sb->shared, taccs, sb->shared->last_task[cookie]);
+		              sb->shared, sb->shared->last_task[cookie]);
+		profile_end("process-image");
 
 		/* pargs.zmq_data will be copied into the image structure, so
 		 * that it can be queried for "header" values etc.  It will
 		 * eventually be freed by image_free() under process_image() */
 
 		if ( sb->profile ) {
-			pthread_mutex_lock(&sb->shared->term_lock);
-			time_accounts_print_short(taccs);
-			pthread_mutex_unlock(&sb->shared->term_lock);
+			profile_print_and_reset();
 		}
-		time_accounts_free(taccs);
 	}
 
 	im_zmq_shutdown(zmqstuff);
@@ -576,7 +577,7 @@ static void remove_pipe(struct sandbox *sb, int d)
 }
 
 
-static void try_read(struct sandbox *sb, TimeAccounts *taccs)
+static void try_read(struct sandbox *sb)
 {
 	int r, i;
 	struct timeval tv;
@@ -584,8 +585,6 @@ static void try_read(struct sandbox *sb, TimeAccounts *taccs)
 	int fdmax;
 	const int ofd = stream_get_fd(sb->stream);
 
-	time_accounts_set(taccs, TACC_SELECT);
-
 	tv.tv_sec = 0;
 	tv.tv_usec = 500000;
 
@@ -619,7 +618,6 @@ static void try_read(struct sandbox *sb, TimeAccounts *taccs)
 
 		/* If the chunk cannot be read, assume the connection
 		 * is broken and that the process will die soon. */
-		time_accounts_set(taccs, TACC_STREAMREAD);
 		if ( pump_chunk(sb->fhs[i], ofd) ) {
 			remove_pipe(sb, i);
 		}
@@ -1066,7 +1064,6 @@ int create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 	struct sigaction sa;
 	int r;
 	int allDone = 0;
-	TimeAccounts *taccs;
 	struct get_pattern_ctx gpctx;
 
 	if ( n_proc > MAX_NUM_WORKERS ) {
@@ -1188,22 +1185,18 @@ int create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 	        return 0;
 	}
 
-	taccs = time_accounts_init();
-
 	do {
 
 		/* Check for stream output from workers */
-		try_read(sb, taccs);
+		try_read(sb);
 
 		/* Check for interrupt or zombies */
-		time_accounts_set(taccs, TACC_SIGNALS);
 		check_signals(sb, semname_q, 1);
 
 		/* Check for hung workers */
 		check_hung_workers(sb);
 
 		/* Top up the queue if necessary */
-		time_accounts_set(taccs, TACC_QUEUETOPUP);
 		pthread_mutex_lock(&sb->shared->queue_lock);
 		if ( !sb->shared->no_more && (sb->shared->n_events < QUEUE_SIZE/2) ) {
 			if ( fill_queue(&gpctx, sb) ) sb->shared->no_more = 1;
@@ -1211,11 +1204,9 @@ int create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 		pthread_mutex_unlock(&sb->shared->queue_lock);
 
 		/* Update progress */
-		time_accounts_set(taccs, TACC_STATUS);
 		try_status(sb, 0);
 
 		/* Have all the events been swallowed? */
-		time_accounts_set(taccs, TACC_ENDCHECK);
 		pthread_mutex_lock(&sb->shared->queue_lock);
 		if ( sb->shared->no_more && (sb->shared->n_events == 0) ) allDone = 1;
 		if ( sb->shared->should_shutdown ) {
@@ -1234,7 +1225,6 @@ int create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 
 	/* Indicate to the workers that we are finished, and wake them up one
 	 * last time */
-	time_accounts_set(taccs, TACC_WAKEUP);
 	STATUS("Waiting for the last patterns to be processed...\n");
 	pthread_mutex_lock(&sb->shared->queue_lock);
 	sb->shared->no_more = 1;
@@ -1244,29 +1234,21 @@ int create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 	}
 	for ( i=0; i<n_proc; i++ ) {
 		int status;
-		time_accounts_set(taccs, TACC_WAITPID);
 		while ( waitpid(sb->pids[i], &status, WNOHANG) == 0 ) {
 
-			time_accounts_set(taccs, TACC_STREAMREAD);
-			try_read(sb, taccs);
+			try_read(sb);
 
-			time_accounts_set(taccs, TACC_SIGNALS);
 			check_signals(sb, semname_q, 0);
 
 			check_hung_workers(sb);
 
-			time_accounts_set(taccs, TACC_STATUS);
 			try_status(sb, 0);
 
-			time_accounts_set(taccs, TACC_WAITPID);
 		}
 		/* If this worker died and got waited by the zombie handler,
 		 * waitpid() returns -1 and the loop still exits. */
 	}
 
-	if ( profile ) time_accounts_print(taccs);
-	time_accounts_free(taccs);
-
 	sem_unlink(semname_q);
 
 	for ( i=0; i<sb->n_read; i++ ) {
diff --git a/src/process_image.c b/src/process_image.c
index 01efb09e..9151528d 100644
--- a/src/process_image.c
+++ b/src/process_image.c
@@ -50,7 +50,7 @@
 #include <integration.h>
 #include <detgeom.h>
 #include <image-msgpack.h>
-#include <time-accounts.h>
+#include <profile.h>
 
 #include "process_image.h"
 #include "predict-refine.h"
@@ -103,7 +103,6 @@ static struct image *file_wait_open_read(const char *filename,
                                          const char *event,
                                          DataTemplate *dtempl,
                                          struct sb_shm *sb_shared,
-                                         TimeAccounts *taccs,
                                          char *last_task,
                                          signed int wait_for_file,
                                          int cookie,
@@ -116,7 +115,6 @@ static struct image *file_wait_open_read(const char *filename,
 	int r;
 	struct image *image;
 
-	time_accounts_set(taccs, TACC_WAITFILE);
 	set_last_task(last_task, "wait for file");
 
 	do {
@@ -150,13 +148,13 @@ static struct image *file_wait_open_read(const char *filename,
 
 	do {
 
-		time_accounts_set(taccs, TACC_IMAGE_DATA);
 		set_last_task(last_task, "read file");
 		sb_shared->pings[cookie]++;
 
-		image = image_read_with_time_accounting(dtempl, filename, event,
-		                                        no_image_data, no_mask_data,
-		                                        taccs);
+		profile_start("image-read");
+		image = image_read(dtempl, filename, event,
+		                   no_image_data, no_mask_data);
+		profile_end("image-read");
 		if ( image == NULL ) {
 			if ( wait_for_file && !read_retry_done ) {
 				read_retry_done = 1;
@@ -178,7 +176,7 @@ static struct image *file_wait_open_read(const char *filename,
 
 void process_image(const struct index_args *iargs, struct pattern_args *pargs,
                    Stream *st, int cookie, const char *tmpdir,
-                   int serial, struct sb_shm *sb_shared, TimeAccounts *taccs,
+                   int serial, struct sb_shm *sb_shared,
                    char *last_task)
 {
 	struct image *image;
@@ -190,25 +188,27 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	int any_crystals;
 
 	if ( pargs->zmq_data != NULL ) {
-		time_accounts_set(taccs, TACC_IMAGE_DATA);
 		set_last_task(last_task, "unpacking messagepack object");
+		profile_start("read-data-block");
 		image = image_read_data_block(iargs->dtempl,
 		                              pargs->zmq_data,
 		                              pargs->zmq_data_size,
 		                              iargs->data_format,
 		                              serial,
 		                              iargs->no_image_data,
-		                              iargs->no_mask_data,
-		                              taccs);
+		                              iargs->no_mask_data);
+		profile_end("read-data-block");
 		if ( image == NULL ) return;
 	} else {
+		profile_start("file-wait-open-read");
 		image = file_wait_open_read(pargs->filename, pargs->event,
 		                            iargs->dtempl,
-		                            sb_shared, taccs, last_task,
+		                            sb_shared, last_task,
 		                            iargs->wait_for_file,
 		                            cookie,
 		                            iargs->no_image_data,
 		                            iargs->no_mask_data);
+		profile_end("file-wait-open-read");
 		if ( image == NULL ) {
 			if ( iargs->wait_for_file != 0 ) {
 				pthread_mutex_lock(&sb_shared->totals_lock);
@@ -222,31 +222,37 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	image->serial = serial;
 
 	/* Take snapshot of image before applying horrible noise filters */
-	time_accounts_set(taccs, TACC_FILTER);
 	set_last_task(last_task, "image filter");
+	profile_start("image-filter");
 	sb_shared->pings[cookie]++;
 
 	if ( (iargs->median_filter > 0) || iargs->noisefilter ) {
+		profile_start("data-backup");
 		prefilter = backup_image_data(image->dp, image->detgeom);
+		profile_end("data-backup");
 	} else {
 		prefilter = NULL;
 	}
 
 	if ( iargs->median_filter > 0 ) {
+		profile_start("median-filter");
 		filter_median(image, iargs->median_filter);
+		profile_end("median-filter");
 	}
 
 	if ( iargs->noisefilter ) {
+		profile_start("noise-filter");
 		filter_noise(image);
+		profile_end("noise-filter");
 	}
+	profile_end("image-filter");
 
-	time_accounts_set(taccs, TACC_RESRANGE);
 	set_last_task(last_task, "resolution range");
 	sb_shared->pings[cookie]++;
 	mark_resolution_range_as_bad(image, iargs->highres, +INFINITY);
 
-	time_accounts_set(taccs, TACC_PEAKSEARCH);
 	sb_shared->pings[cookie]++;
+	profile_start("peak-search");
 	switch ( iargs->peaks ) {
 
 		case PEAK_HDF5:
@@ -326,13 +332,16 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 		break;
 
 	}
+	profile_end("peak-search");
 
 	image->peak_resolution = estimate_peak_resolution(image->features,
 	                                                  image->lambda,
 	                                                  image->detgeom);
 
 	if ( prefilter != NULL ) {
+		profile_start("restore-filter-backup");
 		restore_image_data(image->dp, image->detgeom, prefilter);
+		profile_end("restore-filter-backup");
 	}
 
 	rn = getcwd(NULL, 0);
@@ -369,10 +378,11 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	image->hit = 1;
 
 	/* Index the pattern */
-	time_accounts_set(taccs, TACC_INDEXING);
 	set_last_task(last_task, "indexing");
+	profile_start("index");
 	index_pattern_3(image, iargs->ipriv, &sb_shared->pings[cookie],
 	                last_task);
+	profile_end("index");
 
 	r = chdir(rn);
 	if ( r ) {
@@ -382,7 +392,6 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	free(rn);
 
 	/* Set beam/crystal parameters */
-	time_accounts_set(taccs, TACC_PREDPARAMS);
 	set_last_task(last_task, "prediction params");
 	if ( iargs->fix_profile_r >= 0.0 ) {
 		for ( i=0; i<image->n_crystals; i++ ) {
@@ -406,8 +415,8 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	}
 
 	/* Integrate! */
-	time_accounts_set(taccs, TACC_INTEGRATION);
 	set_last_task(last_task, "integration");
+	profile_start("integration");
 	sb_shared->pings[cookie]++;
 	integrate_all_5(image, iargs->int_meth, PMODEL_XSPHERE,
 	                iargs->push_res,
@@ -415,15 +424,17 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	                iargs->int_diag, iargs->int_diag_h,
 	                iargs->int_diag_k, iargs->int_diag_l,
 	                &sb_shared->term_lock, iargs->overpredict);
+	profile_end("integration");
 
 streamwrite:
-	time_accounts_set(taccs, TACC_WRITESTREAM);
 	set_last_task(last_task, "stream write");
+	profile_start("write-stream");
 	sb_shared->pings[cookie]++;
 	ret = stream_write_chunk(st, image, iargs->stream_flags);
 	if ( ret != 0 ) {
 		ERROR("Error writing stream file.\n");
 	}
+	profile_end("write-stream");
 
 	int n = 0;
 	for ( i=0; i<image->n_crystals; i++ ) {
@@ -436,7 +447,6 @@ streamwrite:
 
 out:
 	/* Count crystals which are still good */
-	time_accounts_set(taccs, TACC_TOTALS);
 	set_last_task(last_task, "process_image finalisation");
 	sb_shared->pings[cookie]++;
 	pthread_mutex_lock(&sb_shared->totals_lock);
diff --git a/src/process_image.h b/src/process_image.h
index a52dd38a..cbf2713b 100644
--- a/src/process_image.h
+++ b/src/process_image.h
@@ -43,7 +43,6 @@ struct index_args;
 
 #include "integration.h"
 #include "im-sandbox.h"
-#include "time-accounts.h"
 #include "peaks.h"
 #include "image.h"
 
@@ -128,8 +127,7 @@ struct pattern_args
 extern void process_image(const struct index_args *iargs,
                           struct pattern_args *pargs, Stream *st,
                           int cookie, const char *tmpdir, int serial,
-                          struct sb_shm *sb_shared, TimeAccounts *taccs,
-                          char *last_task);
+                          struct sb_shm *sb_shared, char *last_task);
 
 
 #endif	/* PROCESS_IMAGE_H */