Merge branch 'better-profiling'

3 files changed, 45 insertions, 55 deletions

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 */