indexamajig: Wall clock profiling

6 files changed, 325 insertions, 10 deletions

diff --git a/src/im-sandbox.c b/src/im-sandbox.c
index 23d3d0a2..bb8edcac 100644
--- a/src/im-sandbox.c
+++ b/src/im-sandbox.c
@@ -3,13 +3,13 @@
  *
  * Sandbox for indexing
  *
- * Copyright © 2012-2015 Deutsches Elektronen-Synchrotron DESY,
+ * Copyright © 2012-2016 Deutsches Elektronen-Synchrotron DESY,
  *                       a research centre of the Helmholtz Association.
  * Copyright © 2012 Richard Kirian
  * Copyright © 2012 Lorenzo Galli
  *
  * Authors:
- *   2010-2015 Thomas White <taw@physics.org>
+ *   2010-2016 Thomas White <taw@physics.org>
  *   2014      Valerio Mariani
  *   2011      Richard Kirian
  *   2012      Lorenzo Galli
@@ -63,6 +63,7 @@
 
 #include "im-sandbox.h"
 #include "process_image.h"
+#include "time-accounts.h"
 
 
 struct sandbox
@@ -244,6 +245,7 @@ static void run_work(const struct index_args *iargs, Stream *st,
                      int cookie, const char *tmpdir, struct sandbox *sb)
 {
 	int allDone = 0;
+	TimeAccounts *taccs = time_accounts_init();
 
 	while ( !allDone ) {
 
@@ -255,6 +257,7 @@ static void run_work(const struct index_args *iargs, Stream *st,
 		int r;
 
 		/* Wait until an event is ready */
+		time_accounts_set(taccs, TACC_EVENTWAIT);
 		if ( sem_wait(sb->queue_sem) != 0 ) {
 			ERROR("Failed to wait on queue semaphore: %s\n",
 			      strerror(errno));
@@ -306,17 +309,20 @@ static void run_work(const struct index_args *iargs, Stream *st,
 		}
 
 		process_image(iargs, &pargs, st, cookie, tmpdir, ser,
-		              sb->shared);
+		              sb->shared, taccs);
 
 		free_filename_plus_event(pargs.filename_p_e);
 
 	}
 
+	time_accounts_set(taccs, TACC_FINALCLEANUP);
 	cleanup_indexing(iargs->indm, iargs->ipriv);
 	free_detector_geometry(iargs->det);
 	free(iargs->hdf5_peak_path);
 	free_copy_hdf5_field_list(iargs->copyme);
 	cell_free(iargs->cell);
+	if ( iargs->profile ) time_accounts_print(taccs);
+	time_accounts_free(taccs);
 }
 
 
@@ -442,7 +448,7 @@ static void remove_pipe(struct sandbox *sb, int d)
 }
 
 
-static void try_read(struct sandbox *sb)
+static void try_read(struct sandbox *sb, TimeAccounts *taccs)
 {
 	int r, i;
 	struct timeval tv;
@@ -450,6 +456,8 @@ static void try_read(struct sandbox *sb)
 	int fdmax;
 	const int ofd = get_stream_fd(sb->stream);
 
+	time_accounts_set(taccs, TACC_SELECT);
+
 	tv.tv_sec = 0;
 	tv.tv_usec = 500000;
 
@@ -483,6 +491,7 @@ static void try_read(struct sandbox *sb)
 
 		/* 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);
 		}
@@ -789,6 +798,7 @@ void create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 	int r;
 	int no_more = 0;
 	int allDone = 0;
+	TimeAccounts *taccs;
 
 	if ( n_proc > MAX_NUM_WORKERS ) {
 		ERROR("Number of workers (%i) is too large.  Using %i\n",
@@ -909,17 +919,21 @@ void create_sandbox(struct index_args *iargs, int n_proc, char *prefix,
 	        return;
 	}
 
+	taccs = time_accounts_init();
+
 	do {
 
 		time_t tNow;
 
 		/* Check for stream output from workers */
-		try_read(sb);
+		try_read(sb, taccs);
 
 		/* Check for interrupt or zombies */
+		time_accounts_set(taccs, TACC_SIGNALS);
 		check_signals(sb, semname_q, 1);
 
 		/* Top up the queue if necessary */
+		time_accounts_set(taccs, TACC_QUEUETOPUP);
 		pthread_mutex_lock(&sb->shared->queue_lock);
 		if ( !no_more && (sb->shared->n_events < QUEUE_SIZE/2) ) {
 			if ( fill_queue(fh, config_basename, iargs->det,
@@ -928,20 +942,25 @@ void 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);
 		tNow = get_monotonic_seconds();
 		if ( tNow > sb->t_last_stats+5 ) try_status(sb, tNow);
 
 		/* Have all the events been swallowed? */
+		time_accounts_set(taccs, TACC_ENDCHECK);
 		pthread_mutex_lock(&sb->shared->queue_lock);
 		if ( no_more && (sb->shared->n_events == 0) ) allDone = 1;
 		pthread_mutex_unlock(&sb->shared->queue_lock);
 
 	} while ( !allDone );
 
+	if ( iargs->profile ) time_accounts_print(taccs);
+
 	fclose(fh);
 
 	/* 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;
@@ -951,14 +970,24 @@ void 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 ) {
-			try_read(sb);
+
+			time_accounts_set(taccs, TACC_STREAMREAD);
+			try_read(sb, taccs);
+
+			time_accounts_set(taccs, TACC_SIGNALS);
 			check_signals(sb, semname_q, 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 ( iargs->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/indexamajig.c b/src/indexamajig.c
index afc41a17..9b32900f 100644
--- a/src/indexamajig.c
+++ b/src/indexamajig.c
@@ -140,6 +140,7 @@ static void show_help(const char *s)
 "     --no-refls-in-stream Do not record integrated reflections in the stream.\n"
 "     --int-diag=<cond>    Show debugging information about reflections.\n"
 "     --no-refine          Skip the prediction refinement step.\n"
+"     --profile            Show timing data for performance monitoring.\n"
 "\nLow-level options for the felix indexer:\n\n"
 "     --felix-options      Change the default arguments passed to the indexer.\n"
 "                          Given as a list of comma separated list of \n"
@@ -243,6 +244,7 @@ int main(int argc, char *argv[])
 	iargs.fix_bandwidth = -1.0;
 	iargs.fix_divergence = -1.0;
 	iargs.felix_options = NULL;
+	iargs.profile = 0;
 
 	/* Long options */
 	const struct option longopts[] = {
@@ -270,6 +272,7 @@ int main(int argc, char *argv[])
 		{"no-revalidate",      0, &iargs.no_revalidate,      1},
 		{"check-hdf5-snr",     0, &iargs.check_hdf5_snr,     1},
 		{"no-refine",          0, &no_refine,                1},
+		{"profile",            0, &iargs.profile,            1},
 
 		/* Long-only options which don't actually do anything */
 		{"no-sat-corr",        0, &iargs.satcorr,            0},
diff --git a/src/process_image.c b/src/process_image.c
index 9b0d79d8..62ef732c 100644
--- a/src/process_image.c
+++ b/src/process_image.c
@@ -52,6 +52,7 @@
 #include "integration.h"
 #include "predict-refine.h"
 #include "im-sandbox.h"
+#include "time-accounts.h"
 
 
 static float **backup_image_data(float **dp, struct detector *det)
@@ -98,7 +99,7 @@ static void restore_image_data(float **dp, struct detector *det, float **bu)
 
 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)
+                   int serial, struct sb_shm *sb_shared, TimeAccounts *taccs)
 {
 	int check;
 	struct hdfile *hdfile;
@@ -122,18 +123,21 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	image.serial = serial;
 	image.indexed_by = INDEXING_NONE;
 
+	time_accounts_set(taccs, TACC_HDF5OPEN);
 	hdfile = hdfile_open(image.filename);
 	if ( hdfile == NULL ) {
 		ERROR("Couldn't open file: %s\n", image.filename);
 		return;
 	}
 
+	time_accounts_set(taccs, TACC_HDF5READ);
 	check = hdf5_read2(hdfile, &image, image.event, 0);
 	if ( check ) {
 		return;
 	}
 
 	/* Take snapshot of image before applying horrible noise filters */
+	time_accounts_set(taccs, TACC_FILTER);
 	prefilter = backup_image_data(image.dp, image.det);
 
 	if ( iargs->median_filter > 0 ) {
@@ -144,8 +148,10 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 		filter_noise(&image);
 	}
 
+	time_accounts_set(taccs, TACC_RESRANGE);
 	mark_resolution_range_as_bad(&image, iargs->highres, +INFINITY);
 
+	time_accounts_set(taccs, TACC_PEAKSEARCH);
 	switch ( iargs->peaks ) {
 
 		case PEAK_HDF5:
@@ -207,6 +213,7 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	}
 
 	/* Index the pattern */
+	time_accounts_set(taccs, TACC_INDEXING);
 	index_pattern(&image, iargs->indm, iargs->ipriv);
 
 	r = chdir(rn);
@@ -218,6 +225,7 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	free(rn);
 
 	/* Set beam/crystal parameters */
+	time_accounts_set(taccs, TACC_PREDPARAMS);
 	if ( iargs->fix_profile_r >= 0.0 ) {
 		for ( i=0; i<image.n_crystals; i++ ) {
 			crystal_set_profile_radius(image.crystals[i],
@@ -238,6 +246,7 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	}
 
 	/* Integrate! */
+	time_accounts_set(taccs, TACC_INTEGRATION);
 	integrate_all_4(&image, iargs->int_meth, PMODEL_SCSPHERE,
 	                iargs->push_res,
 	                iargs->ir_inn, iargs->ir_mid, iargs->ir_out,
@@ -245,6 +254,7 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	                iargs->int_diag_k, iargs->int_diag_l,
 	                &sb_shared->term_lock);
 
+	time_accounts_set(taccs, TACC_WRITESTREAM);
 	ret = write_chunk(st, &image, hdfile,
 	                  iargs->stream_peaks, iargs->stream_refls,
 	                  pargs->filename_p_e->ev);
@@ -263,6 +273,7 @@ void process_image(const struct index_args *iargs, struct pattern_args *pargs,
 	}
 
 	/* Count crystals which are still good */
+	time_accounts_set(taccs, TACC_TOTALS);
 	pthread_mutex_lock(&sb_shared->totals_lock);
 	any_crystals = 0;
 	for ( i=0; i<image.n_crystals; i++ ) {
diff --git a/src/process_image.h b/src/process_image.h
index f474725c..d41c23f5 100644
--- a/src/process_image.h
+++ b/src/process_image.h
@@ -3,11 +3,11 @@
  *
  * The processing pipeline for one image
  *
- * Copyright © 2012-2015 Deutsches Elektronen-Synchrotron DESY,
+ * Copyright © 2012-2016 Deutsches Elektronen-Synchrotron DESY,
  *                       a research centre of the Helmholtz Association.
  *
  * Authors:
- *   2010-2015 Thomas White <taw@physics.org>
+ *   2010-2016 Thomas White <taw@physics.org>
  *   2014      Valerio Mariani
  *
  * This file is part of CrystFEL.
@@ -38,6 +38,7 @@ struct index_args;
 
 #include "integration.h"
 #include "im-sandbox.h"
+#include "time-accounts.h"
 
 
 enum {
@@ -89,6 +90,7 @@ struct index_args
 	float fix_bandwidth;
 	float fix_divergence;
 	char *felix_options;
+	int profile;  /* Whether or not to do wall clock profiling */
 };
 
 
@@ -103,7 +105,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);
+                          struct sb_shm *sb_shared, TimeAccounts *taccs);
 
 
 #endif	/* PROCESS_IMAGE_H */
diff --git a/src/time-accounts.c b/src/time-accounts.c
new file mode 100644
index 00000000..2ff22d6c
--- /dev/null
+++ b/src/time-accounts.c
@@ -0,0 +1,199 @@
+/*
+ * time-accounts.c
+ *
+ * Simple profiling according to wall clock time
+ *
+ * Copyright © 2016 Deutsches Elektronen-Synchrotron DESY,
+ *                  a research centre of the Helmholtz Association.
+ *
+ * Authors:
+ *  2016 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/>.
+ *
+ */
+
+#ifdef HAVE_CONFIG_H
+#include <config.h>
+#endif
+
+#include <stdlib.h>
+#include <stdio.h>
+#include <string.h>
+#include <time.h>
+#include <assert.h>
+
+#include "time-accounts.h"
+
+#define MAX_ACCOUNTS 256
+
+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;
+
+	return accs;
+}
+
+
+void time_accounts_free(TimeAccounts *accs)
+{
+	free(accs);
+}
+
+
+static int find_account(TimeAccounts *accs, enum timeaccount acc)
+{
+	int i;
+	static int warned_toomany = 0;
+
+	for ( i=0; i<accs->n_accs; i++ ) {
+		if ( accs->accs[i] == acc ) return i;
+	}
+
+	if ( i == MAX_ACCOUNTS ) {
+		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;
+}
+
+
+#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_HDF5OPEN : return "Opening HDF5 file";
+		case TACC_HDF5READ : return "Reading HDF5 file";
+		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";
+	}
+}
+
+
+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/src/time-accounts.h b/src/time-accounts.h
new file mode 100644
index 00000000..92b459e1
--- /dev/null
+++ b/src/time-accounts.h
@@ -0,0 +1,71 @@
+/*
+ * time-accounts.h
+ *
+ * Simple profiling according to wall clock time
+ *
+ * Copyright © 2016 Deutsches Elektronen-Synchrotron DESY,
+ *                  a research centre of the Helmholtz Association.
+ *
+ * Authors:
+ *  2016 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
+
+#ifdef HAVE_CONFIG_H
+#include <config.h>
+#endif
+
+enum timeaccount
+{
+	TACC_NOTHING,
+	TACC_STREAMREAD,
+	TACC_SELECT,
+	TACC_SIGNALS,
+	TACC_QUEUETOPUP,
+	TACC_STATUS,
+	TACC_ENDCHECK,
+	TACC_WAKEUP,
+	TACC_WAITPID,
+	TACC_HDF5OPEN,
+	TACC_HDF5READ,
+	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_print(TimeAccounts *accs);
+
+#endif	/* TIME_ACCOUNTS_H */