aboutsummaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorThomas White <taw@physics.org>2016-03-01 02:59:38 -0800
committerThomas White <taw@physics.org>2016-03-01 03:37:24 -0800
commitc780ec9c40325c257fff73c1d330c5f4d81baea9 (patch)
tree2c633bddd6479c59b595037c879ea3227d1bec93
parent0c1a3d2a45878b544c0f30135fc9d1240f88889a (diff)
indexamajig: Wall clock profiling
-rw-r--r--Makefile.am4
-rw-r--r--doc/man/indexamajig.15
-rw-r--r--src/im-sandbox.c41
-rw-r--r--src/indexamajig.c3
-rw-r--r--src/process_image.c13
-rw-r--r--src/process_image.h8
-rw-r--r--src/time-accounts.c199
-rw-r--r--src/time-accounts.h71
8 files changed, 332 insertions, 12 deletions
diff --git a/Makefile.am b/Makefile.am
index ae4b2913..799fab27 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -74,7 +74,7 @@ src_process_hkl_SOURCES = src/process_hkl.c
src_list_events_SOURCES = src/list_events.c
src_indexamajig_SOURCES = src/indexamajig.c src/im-sandbox.c \
- src/process_image.c
+ src/process_image.c src/time-accounts.c
if BUILD_HDFSEE
src_hdfsee_SOURCES = src/hdfsee.c src/dw-hdfsee.c src/hdfsee-render.c
@@ -133,7 +133,7 @@ EXTRA_DIST += src/dw-hdfsee.h src/hdfsee.h src/render_hkl.h \
src/cl-utils.h src/hdfsee-render.h src/diffraction.h \
src/diffraction-gpu.h src/pattern_sim.h src/list_tmp.h \
src/im-sandbox.h src/process_image.h src/multihistogram.h \
- src/rejection.h src/scaling.h
+ src/rejection.h src/scaling.h src/time-accounts.h
crystfeldir = $(datadir)/crystfel
crystfel_DATA = data/diffraction.cl data/hdfsee.ui
diff --git a/doc/man/indexamajig.1 b/doc/man/indexamajig.1
index d047f86f..9b5873bb 100644
--- a/doc/man/indexamajig.1
+++ b/doc/man/indexamajig.1
@@ -353,6 +353,11 @@ You do not have to use all three of these options together. For example, if the
Skip the prediction refinement step.
.PD 0
+.IP \fB--profile
+.PD
+Display timing data for performance monitoring.
+
+.PD 0
.IP \fB--felix-options\fR
.PD
Specify a comma-separated list of keyword arguments to change the default parameters passed to the felix indexer. For asthetics, this list can also be preceeded and followed by quotations - as in: \fB--felix-options="arg1=10,arg2=600"\fR. A list of parameters which can be modified through this option is detailed below.
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 */