diff options
| -rw-r--r-- | Makefile.am | 4 | ||||
| -rw-r--r-- | doc/man/indexamajig.1 | 5 | ||||
| -rw-r--r-- | src/im-sandbox.c | 41 | ||||
| -rw-r--r-- | src/indexamajig.c | 3 | ||||
| -rw-r--r-- | src/process_image.c | 13 | ||||
| -rw-r--r-- | src/process_image.h | 8 | ||||
| -rw-r--r-- | src/time-accounts.c | 199 | ||||
| -rw-r--r-- | src/time-accounts.h | 71 |
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 */ |