diff --git a/ChangeLog b/ChangeLog index badc120..b0cf883 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,3 +1,8 @@ +2020-03-16 Timo Lassmann + + * version 3.2.3 + - replaced timing code with code from the easel lib. + 2020-02-23 Timo Lassmann * version 3.2.2 diff --git a/configure.ac b/configure.ac index 6913b7f..47350dc 100644 --- a/configure.ac +++ b/configure.ac @@ -1,5 +1,5 @@ -AC_INIT(kalign, 3.2.2) +AC_INIT(kalign, 3.2.3) #AC_CONFIG_AUX_DIR([.]) @@ -7,7 +7,7 @@ AC_USE_SYSTEM_EXTENSIONS AM_INIT_AUTOMAKE AC_PROG_CC AC_PROG_CXX -AC_PROG_RANLIB +#AC_PROG_RANLIB AC_PROG_INSTALL AM_SILENT_RULES([no]) @@ -91,30 +91,38 @@ AC_PROG_INSTALL AC_CHECK_LIB([m], [sqrt]) AC_CHECK_LIB([pthread], [main]) -AC_SEARCH_LIBS([clock_gettime],[rt]) +AC_SEARCH_LIBS([clock_gettime],[rt posix]) # Checks for header files. AC_CHECK_HEADERS([math.h float.h stdlib.h unistd.h]) AC_CHECK_HEADERS([sys/time.h]) + +AC_CHECK_HEADERS([mach/mach.h]) + AC_CHECK_HEADERS([limits.h]) + AC_C_INLINE +AC_TYPE_SIZE_T +AC_TYPE_SSIZE_T + +AC_TYPE_INT8_T AC_TYPE_INT32_T AC_TYPE_INT64_T -AC_TYPE_INT8_T -AC_TYPE_SIZE_T + +AC_TYPE_UINT8_T AC_TYPE_UINT16_T AC_TYPE_UINT32_T AC_TYPE_UINT64_T -AC_TYPE_UINT8_T # Checks for library functions. AC_FUNC_MALLOC AC_FUNC_REALLOC AC_FUNC_STRNLEN AC_FUNC_ERROR_AT_LINE AC_CHECK_FUNCS([gettimeofday pow realpath sqrt strstr memset]) - - +AC_CHECK_FUNCS([clock_gettime]) +AC_CHECK_FUNCS([gethrtime]) +AC_CHECK_FUNCS([gettimeofday]) AC_CANONICAL_HOST case $host_os in diff --git a/src/Makefile.am b/src/Makefile.am index a6f6a47..84bb434 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -17,6 +17,8 @@ bin_PROGRAMS = timescorealn kalign kalign_SOURCES = run_kalign.c \ tldevel.h \ tldevel.c \ +esl_stopwatch.h \ +esl_stopwatch.c \ rng.h \ rng.c \ global.h \ @@ -56,6 +58,8 @@ TESTS = edist alphabet misc_test bpm_test rstdin_test rwaln_SOURCES = \ tldevel.h \ tldevel.c \ +esl_stopwatch.h \ +esl_stopwatch.c \ rwalign.c \ alphabet.h \ alphabet.c \ @@ -65,6 +69,8 @@ rwaln_CPPFLAGS = $(AM_CPPFLAGS) -DRWALIGN_TEST timescorealn_SOURCES = \ tldevel.h \ tldevel.c \ +esl_stopwatch.h \ +esl_stopwatch.c \ time_and_score_aln.c \ msa.h \ parameters.h \ @@ -79,6 +85,8 @@ misc.c bpm_test_SOURCES = \ tldevel.h \ tldevel.c \ +esl_stopwatch.h \ +esl_stopwatch.c \ rng.h \ rng.c \ bpm.h \ @@ -109,6 +117,8 @@ alphabet_CPPFLAGS = $(AM_CPPFLAGS) -DITEST_ALPHABET edist_SOURCES = \ tldevel.h \ tldevel.c \ +esl_stopwatch.h \ +esl_stopwatch.c \ rng.h \ rng.c \ euclidean_dist.h \ diff --git a/src/bisectingKmeans.c b/src/bisectingKmeans.c index 2b8174b..9ad6288 100644 --- a/src/bisectingKmeans.c +++ b/src/bisectingKmeans.c @@ -30,7 +30,7 @@ #include "alignment.h" #include "pick_anchor.h" - +#include "esl_stopwatch.h" struct node{ struct node* left; struct node* right; @@ -90,8 +90,8 @@ int build_tree_kmeans(struct msa* msa, struct aln_param* ap) RUNP(dm = d_estimation(msa, anchors, num_anchors,0));//les,int pair) STOP_TIMER(timer); - - LOG_MSG("Done in %f sec.", GET_TIMING(timer)); + GET_TIMING(timer); + //LOG_MSG("Done in %f sec.", GET_TIMING(timer)); MFREE(anchors); @@ -111,8 +111,8 @@ int build_tree_kmeans(struct msa* msa, struct aln_param* ap) RUNP(root = bisecting_kmeans(msa,root, dm, samples, numseq, num_anchors, numseq, ap->rng)); STOP_TIMER(timer); - - LOG_MSG("Done in %f sec.", GET_TIMING(timer)); + GET_TIMING(timer); + //LOG_MSG("Done in %f sec.", GET_TIMING(timer)); label_internal(root, numseq); @@ -126,7 +126,7 @@ int build_tree_kmeans(struct msa* msa, struct aln_param* ap) _mm_free(dm[i]); } MFREE(dm); - + DESTROY_TIMER(timer); return OK; ERROR: return FAIL; diff --git a/src/bpm.c b/src/bpm.c index 9e8fb61..a9fb48c 100644 --- a/src/bpm.c +++ b/src/bpm.c @@ -25,6 +25,8 @@ #include "rng.h" + + #ifdef HAVE_AVX2 #include @@ -40,7 +42,9 @@ __m256i bitShiftRight256ymm (__m256i *data, int count); /* Below are test functions */ #ifdef BPM_UTEST + #include "alphabet.h" +#include "esl_stopwatch.h" /* Functions needed for the unit test*/ uint8_t dyn_256(const uint8_t* t,const uint8_t* p,int n,int m); @@ -177,19 +181,25 @@ int bpm_test(void) double dyn_timing; double bpm_timing; int timing_iter = 100; - fprintf(stdout,"Dyn\tAVX\tDYN/AVX\n"); + //fprintf(stdout,"Dyn\tAVX\tDYN/AVX\n"); DECLARE_TIMER(t); + + START_TIMER(t); for(i = 0; i < 100;i+=10){ RUN(mutate_seq(b,len,i,alphabet->L,rng)); - START_TIMER(t); + for(j = 0; j < timing_iter;j++){ dyn_score = dyn_256(a,b,len,len); } - STOP_TIMER(t); - dyn_timing = GET_TIMING(t); + //dyn_timing = GET_TIMING(t); + } + STOP_TIMER(t); + GET_TIMING(t); + START_TIMER(t); + for(i = 0; i < 100;i+=10){ + RUN(mutate_seq(b,len,i,alphabet->L,rng)); - START_TIMER(t); #ifdef HAVE_AVX2 for(j = 0; j < timing_iter;j++){ bpm_score = bpm_256(a,b,len,len); @@ -197,18 +207,19 @@ int bpm_test(void) #else bpm_score = dyn_score; #endif - STOP_TIMER(t); - bpm_timing = GET_TIMING(t); - ASSERT(dyn_score == bpm_score, "Scores differ: %d %d.",dyn_score, bpm_score); - fprintf(stdout,"%f\t%f\t%f\n",dyn_timing,bpm_timing, dyn_timing / bpm_timing); + //ASSERT(dyn_score == bpm_score, "Scores differ: %d %d.",dyn_score, bpm_score); + //fprintf(stdout,"%f\t%f\t%f\n",dyn_timing,bpm_timing, dyn_timing / bpm_timing); /* restore seq */ for(j = 0;j < len;j++){ b[j] = a[j]; } } + STOP_TIMER(t); + GET_TIMING(t); + DESTROY_TIMER(t); MFREE(alphabet); MFREE(a); MFREE(b); diff --git a/src/esl_stopwatch.c b/src/esl_stopwatch.c new file mode 100644 index 0000000..f369354 --- /dev/null +++ b/src/esl_stopwatch.c @@ -0,0 +1,438 @@ +/* Tracking cpu/system/elapsed time used by a process. + * + * Credits: + * - Thanks to Warren Gish for assistance. + * - Includes portable high-resolution timer code + * (C) 2012 David Robert Nadeau, http://NadeauSoftware.com/ + * Creative Commons Attribution 3.0 Unported License + * http://creativecommons.org/licenses/by/3.0/deed.en_US + */ +//#include "esl_config.h" + +//#include "easel.h" +#include "esl_stopwatch.h" + +#define TRUE 1 + +static double stopwatch_getRealTime(void); + +/***************************************************************** + * ESL_STOPWATCH object maintenance + *****************************************************************/ + +/* Function: esl_stopwatch_Create() + * + * Purpose: Creates a new stopwatch. + * + * Returns: ptr to a new object; caller is + * responsible for free'ing it with + * . + * + * Throws: NULL on allocation failure. + */ +ESL_STOPWATCH * esl_stopwatch_Create(void) +{ + ESL_STOPWATCH *w = NULL; + int status; + + MMALLOC(w, sizeof(ESL_STOPWATCH)); + //ESL_ALLOC(w, sizeof(ESL_STOPWATCH)); + w->elapsed = 0.; + w->user = 0.; + w->sys = 0.; + return w; + +ERROR: + esl_stopwatch_Destroy(w); + return NULL; +} + +/* Function: esl_stopwatch_Destroy() + * + * Purpose: Frees an . + */ +void esl_stopwatch_Destroy(ESL_STOPWATCH *w) +{ + if (w){ + free(w); + } +} + + + +/* Function: esl_stopwatch_Start() + * + * Purpose: Start a stopwatch. This sets the base + * for elapsed, cpu, and system time difference + * calculations by subsequent calls to + * . + * + * Returns: on success. + */ +int esl_stopwatch_Start(ESL_STOPWATCH *w) +{ +#if defined HAVE_TIMES && defined eslSTOPWATCH_HIGHRES /* System-dependent highest resolution */ + times(&(w->cpu0)); + w->t0 = stopwatch_getRealTime(); +#elif HAVE_TIMES /* ... else fall back to POSIX... */ + w->t0 = times(&(w->cpu0)); +#else /* ... else fallback to ANSI C */ + w->t0 = time(NULL); + w->cpu0 = clock(); +#endif + + w->elapsed = 0.; + w->user = 0.; + w->sys = 0.; + return OK; +} + +/* Function: esl_stopwatch_Stop() + * + * Purpose: Stop a stopwatch. Record and store elapsed, + * cpu, and system time difference relative to the + * last call to . + * + * Returns: on success. + */ +int esl_stopwatch_Stop(ESL_STOPWATCH *w) +{ +#if defined eslSTOPWATCH_HIGHRES && defined HAVE_TIMES + double t1; + struct tms cpu1; + double clk_tck; +#elif defined HAVE_TIMES + clock_t t1; + struct tms cpu1; + double clk_tck; +#else + time_t t1; + clock_t cpu1; +#endif + + +#if defined eslSTOPWATCH_HIGHRES && defined HAVE_TIMES + t1 = stopwatch_getRealTime(); + w->elapsed = t1 - w->t0; + clk_tck = (double) sysconf(_SC_CLK_TCK); + times(&cpu1); + w->user = (double) (cpu1.tms_utime + cpu1.tms_cutime - + w->cpu0.tms_utime - w->cpu0.tms_cutime) / clk_tck; + w->sys = (double) (cpu1.tms_stime + cpu1.tms_cstime - + w->cpu0.tms_stime - w->cpu0.tms_cstime) / clk_tck; +#elif defined HAVE_TIMES /* POSIX */ + t1 = times(&cpu1); + clk_tck = (double) sysconf(_SC_CLK_TCK); + w->elapsed = (double) (t1 - w->t0) / clk_tck; + w->user = (double) (cpu1.tms_utime + cpu1.tms_cutime - + w->cpu0.tms_utime - w->cpu0.tms_cutime) / clk_tck; + w->sys = (double) (cpu1.tms_stime + cpu1.tms_cstime - + w->cpu0.tms_stime - w->cpu0.tms_cstime) / clk_tck; +#else /* fallback to ANSI C */ + t1 = time(NULL); + cpu1 = clock(); + w->elapsed = difftime(t1, w->t0); + w->user = (double) (cpu1- w->cpu0) / (double) CLOCKS_PER_SEC; + w->sys = 0.; /* no way to portably get system time in ANSI C */ +#endif + + return OK; +} + +/* format_time_string() + * Date: SRE, Fri Nov 26 15:06:28 1999 [St. Louis] + * + * Purpose: Given a number of seconds, format into + * hh:mm:ss.xx in a provided buffer. + * + * Args: buf - allocated space (128 is plenty!) + * sec - number of seconds + * do_frac - TRUE (1) to include hundredths of a sec + */ +static void format_time_string(char *buf, double sec, int do_frac) +{ + int h, m, s, hs; + + h = (int) (sec / 3600.); + m = (int) (sec / 60.) - h * 60; + s = (int) (sec) - h * 3600 - m * 60; + if (do_frac) { + hs = (int) (sec * 100.) - h * 360000 - m * 6000 - s * 100; + sprintf(buf, "%02d:%02d:%02d.%02d", h,m,s,hs); + } else { + sprintf(buf, "%02d:%02d:%02d", h,m,s); + } +} + +/* Function: esl_stopwatch_Display() + * + * Purpose: Output a usage summary line from a stopped + * stopwatch, showing elapsed, cpu, and system time + * between the last calls to + * and . + * + * The string will be prepended to the output + * line. Use <""> to prepend nothing. If is NULL, + * a default <"CPU Time: "> prefix is used. + * + * For = <"CPU Time: "> an example output line is:\\ + * + * + * Args: fp - output stream + * w - stopped stopwatch + * prefix - output line prefix ("" for nothing) + * + * Returns: on success. + * + * Throws: on any system write error, such as filled disk. + */ +int esl_stopwatch_Display(FILE *fp, ESL_STOPWATCH *w, char *prefix) +{ + char buf[128]; /* (safely holds up to 10^14 years; I'll be dead by then) */ + + if (prefix == NULL) { + if (fputs("CPU Time: ", fp) < 0){ + ERROR_MSG( "stopwatch display write failed"); + } + }else{ + if (fputs(prefix, fp) < 0){ + ERROR_MSG( "stopwatch display write failed"); + } + } + + format_time_string(buf, w->user+w->sys, TRUE); +#ifdef HAVE_TIMES + if (fprintf(fp, "%.2fu %.2fs %s ", w->user, w->sys, buf) < 0){ + ERROR_MSG( "stopwatch display write failed"); + } +#else + if (fprintf(fp, "%.2fu %s ", w->user, buf) < 0){ + ERROR_MSG( "stopwatch display write failed"); + } +#endif + format_time_string(buf, w->elapsed, TRUE); + if (fprintf(fp, "Elapsed: %s\n", buf) < 0){ + ERROR_MSG( "stopwatch display write failed"); + } + return OK; +ERROR: + return FAIL; +} + +int tl_stopwatch_Display(ESL_STOPWATCH *w) +{ + char buf[128]; /* (safely holds up to 10^14 years; even I'll be dead by then) */ + char buf2[128]; /* (safely holds up to 10^14 years; even I'll be dead by then) */ + format_time_string(buf, w->user+w->sys, TRUE); + format_time_string(buf2, w->elapsed, TRUE); +#ifdef HAVE_TIMES + LOG_MSG("CPU Time: %.2fu %.2fs %s Elapsed: %s", w->user, w->sys, buf,buf2); + +#else + LOG_MSG("CPU Time: %.2fu %s Elapsed: %s", w->user, buf,buf2); +#endif + return OK; +} + + +/* Function: esl_stopwatch_GetElapsed() + * Synopsis: Return the elapsed time in seconds + * Incept: SRE, Fri Jan 8 10:10:37 2016 + * + * Purpose: After watch is Stop()'ed, calling + * returns the elapsed time + * in seconds. + * + * The resolution is system-dependent. + */ +double esl_stopwatch_GetElapsed(ESL_STOPWATCH *w) +{ + return w->elapsed; +} + + +/* Function: esl_stopwatch_Include() + * + * Purpose: Merge the cpu and system times from a slave into + * a master stopwatch. Both watches must be + * stopped, and should not be stopped again unless + * You Know What You're Doing. + * + * Elapsed time is not merged. Master is assumed + * to be keeping track of the wall clock (real) time, + * and the slave/worker watch is ignored. + * + * Useful in at least two cases. One is in + * PVM, where we merge in the stopwatch(es) from separate + * process(es) in a cluster. A second is in + * threads, for broken pthreads/times() implementations + * that lose track of cpu times used by spawned + * threads. + * + * Args: master - stopwatch that's aggregating times + * w - watch to add to the master. + * + * Returns: on success. + */ +int esl_stopwatch_Include(ESL_STOPWATCH *master, ESL_STOPWATCH *w) +{ + master->user += w->user; + master->sys += w->sys; + return OK; +} + + +/***************************************************************** + * Portable high resolution timing + *****************************************************************/ +#ifdef eslSTOPWATCH_HIGHRES + +/* The following code is + * (C) 2012 David Robert Nadeau, http://NadeauSoftware.com + * Creative Commons Attribution 3.0 Unported License + * http://creativecommons.org/licenses/by/3.0/deed.en_US + * + * Reference: http://nadeausoftware.com/articles/2012/04/c_c_tip_how_measure_elapsed_real_time_benchmarking + * + * On resolution: + * I believe that on Mac OS/X, the high performance timer has a resolution in units + * of nanoseconds (at least on some platforms, including my laptop). However, calling + * the esl_stopwatch_* functions themselves have overhead. The example driver is + * a reasonable test of the minimal resolution, including call overhead; that gives + * me about 0.1 microseconds (12 Jan 2016). + */ +#if defined(_WIN32) +#include + +#elif defined(__unix__) || defined(__unix) || defined(unix) || (defined(__APPLE__) && defined(__MACH__)) +#include /* POSIX flags */ +#include /* clock_gettime(), time() */ +#include /* gethrtime(), gettimeofday() */ + +#if defined(__MACH__) && defined(__APPLE__) +#include +#include +#endif + +#else +#error "Unable to define getRealTime( ) for an unknown OS." +#endif + +/** + * Returns the real time, in seconds, or -1.0 if an error occurred. + * + * Time is measured since an arbitrary and OS-dependent start time. + * The returned real time is only useful for computing an elapsed time + * between two calls to this function. + */ +static double stopwatch_getRealTime(void) +{ +#if defined(_WIN32) + FILETIME tm; + ULONGLONG t; +#if defined(NTDDI_WIN8) && NTDDI_VERSION >= NTDDI_WIN8 + /* Windows 8, Windows Server 2012 and later. ---------------- */ + GetSystemTimePreciseAsFileTime( &tm ); +#else + /* Windows 2000 and later. ---------------------------------- */ + GetSystemTimeAsFileTime( &tm ); +#endif + t = ((ULONGLONG)tm.dwHighDateTime << 32) | (ULONGLONG)tm.dwLowDateTime; + return (double)t / 10000000.0; + +#elif (defined(__hpux) || defined(hpux)) || ((defined(__sun__) || defined(__sun) || defined(sun)) && (defined(__SVR4) || defined(__svr4__))) + /* HP-UX, Solaris. ------------------------------------------ */ + return (double)gethrtime( ) / 1000000000.0; + +#elif defined(__MACH__) && defined(__APPLE__) + /* OSX. ----------------------------------------------------- */ + static double timeConvert = 0.0; + if ( timeConvert == 0.0 ) + { + mach_timebase_info_data_t timeBase; + (void)mach_timebase_info( &timeBase ); + timeConvert = (double)timeBase.numer / + (double)timeBase.denom / + 1000000000.0; + } + return (double)mach_absolute_time( ) * timeConvert; + +#elif defined(_POSIX_VERSION) + /* POSIX. --------------------------------------------------- */ +#if defined(_POSIX_TIMERS) && (_POSIX_TIMERS > 0) + { + struct timespec ts; +#if defined(CLOCK_MONOTONIC_PRECISE) + /* BSD. --------------------------------------------- */ + const clockid_t id = CLOCK_MONOTONIC_PRECISE; +#elif defined(CLOCK_MONOTONIC_RAW) + /* Linux. ------------------------------------------- */ + const clockid_t id = CLOCK_MONOTONIC_RAW; +#elif defined(CLOCK_HIGHRES) + /* Solaris. ----------------------------------------- */ + const clockid_t id = CLOCK_HIGHRES; +#elif defined(CLOCK_MONOTONIC) + /* AIX, BSD, Linux, POSIX, Solaris. ----------------- */ + const clockid_t id = CLOCK_MONOTONIC; +#elif defined(CLOCK_REALTIME) + /* AIX, BSD, HP-UX, Linux, POSIX. ------------------- */ + const clockid_t id = CLOCK_REALTIME; +#else + const clockid_t id = (clockid_t)-1; /* Unknown. */ +#endif /* CLOCK_* */ + if ( id != (clockid_t)-1 && clock_gettime( id, &ts ) != -1 ) + return (double)ts.tv_sec + + (double)ts.tv_nsec / 1000000000.0; + /* Fall thru. */ + } +#endif /* _POSIX_TIMERS */ + + /* AIX, BSD, Cygwin, HP-UX, Linux, OSX, POSIX, Solaris. ----- */ + struct timeval tm; + gettimeofday( &tm, NULL ); + return (double)tm.tv_sec + (double)tm.tv_usec / 1000000.0; +#else + return -1.0; /* Failed. */ +#endif +} +#endif /*eslSTOPWATCH_HIGHRES*/ + +/***************************************************************** + * Example of using the stopwatch module + *****************************************************************/ +#ifdef eslSTOPWATCH_EXAMPLE +/*::cexcerpt::stopwatch_example::begin::*/ +/* compile: gcc -g -Wall -I. -o example -DeslSTOPWATCH_EXAMPLE esl_stopwatch.c easel.c -lm + * run: ./example + */ +#include "easel.h" +#include "esl_stopwatch.h" + +int main(void) +{ + ESL_STOPWATCH *w; + double t = 0.; + + w = esl_stopwatch_Create(); + + /* This tests the minimum *practical* resolution of the clock, + * inclusive of overhead of calling the stopwatch functions. + * It gives me ~0.1 usec (12 Jan 2016). + */ + esl_stopwatch_Start(w); + while (t == 0.) + { + esl_stopwatch_Stop(w); + t = esl_stopwatch_GetElapsed(w); + } + + printf("Elapsed time clock has practical resolution of around: %g sec\n", t); + + esl_stopwatch_Display(stdout, w, "CPU Time: "); + esl_stopwatch_Destroy(w); + return 0; +} +/*::cexcerpt::stopwatch_example::end::*/ +#endif /*ESL_STOPWATCH_EXAMPLE*/ + + diff --git a/src/esl_stopwatch.h b/src/esl_stopwatch.h new file mode 100644 index 0000000..7ac3f0b --- /dev/null +++ b/src/esl_stopwatch.h @@ -0,0 +1,67 @@ +/* Tracking cpu/system/elapsed time used by a process. + * + * SRE, Wed Feb 22 19:30:36 2006 [St. Louis] [moved to Easel] + * SRE, Thu Aug 3 08:00:35 2000 [St. Louis] [moved to SQUID] + * SRE, Fri Nov 26 14:54:21 1999 [St. Louis] [HMMER] + */ +#ifndef eslSTOPWATCH_INCLUDED +#define eslSTOPWATCH_INCLUDED + +#include "tldevel.h" +//#include "esl_config.h" + + + +#include +#ifdef HAVE_TIMES +#include +#endif +#ifdef HAVE_UNISTD_H +#include /* need for sysconf() */ +#endif + +typedef struct { +#ifdef eslSTOPWATCH_HIGHRES + double t0; /* baseline wall time from Nadeau routine */ +#elif HAVE_TIMES + clock_t t0; /* baseline wall time, POSIX times() */ +#else + time_t t0; /* baseline wall time from ANSI time() */ +#endif + +#ifdef HAVE_TIMES + struct tms cpu0; /* baseline CPU/system time, POSIX times() */ +#else + clock_t cpu0; /* baseline CPU time, fallback to ANSI clock() */ +#endif + + /* elapsed/user/sys are t-t0 results for the last time the + * watch was Stop()'ed. + */ + double elapsed; /* elapsed wall time, seconds */ + double user; /* CPU time, seconds */ + double sys; /* system time, seconds */ +} ESL_STOPWATCH; + + +extern ESL_STOPWATCH *esl_stopwatch_Create(void); +extern void esl_stopwatch_Destroy(ESL_STOPWATCH *w); + +extern int esl_stopwatch_Start(ESL_STOPWATCH *w); +extern int esl_stopwatch_Stop(ESL_STOPWATCH *w); +extern int esl_stopwatch_Display(FILE *fp, ESL_STOPWATCH *w, char *prefix); +extern int tl_stopwatch_Display(ESL_STOPWATCH *w); +extern double esl_stopwatch_GetElapsed(ESL_STOPWATCH *w); + +extern int esl_stopwatch_Include(ESL_STOPWATCH *master, ESL_STOPWATCH *w); + + +#define DECLARE_TIMER(n) ESL_STOPWATCH* timer_##n = esl_stopwatch_Create(); + +#define START_TIMER(n) esl_stopwatch_Start(timer_##n); +#define STOP_TIMER(n) esl_stopwatch_Stop(timer_##n); +#define GET_TIMING(n) tl_stopwatch_Display(timer_##n); + +#define DESTROY_TIMER(n) esl_stopwatch_Destroy(timer_##n); + +#endif /*eslSTOPWATCH_INCLUDED*/ diff --git a/src/euclidean_dist.c b/src/euclidean_dist.c index 5e8dd28..1e6803b 100644 --- a/src/euclidean_dist.c +++ b/src/euclidean_dist.c @@ -25,6 +25,8 @@ #include #include #include "float.h" + +#include "esl_stopwatch.h" /* These functions were taken from: */ /* https://stackoverflow.com/questions/6996764/fastest-way-to-do-horizontal-float-vector-sum-on-x86 */ float hsum256_ps_avx(__m256 v); @@ -87,7 +89,8 @@ int main(void) } } STOP_TIMER(t); - LOG_MSG("%f\tsec.",GET_TIMING(t)); + GET_TIMING(t); + //LOG_MSG("%f\tsec.",GET_TIMING(t)); #ifdef HAVE_AVX2 LOG_MSG("Timing AVX"); @@ -102,7 +105,8 @@ int main(void) } } STOP_TIMER(t); - LOG_MSG("%f\tsec.",GET_TIMING(t)); + GET_TIMING(t); + //LOG_MSG("%f\tsec.",GET_TIMING(t)); #endif for(i = 0; i < 100;i++){ @@ -111,6 +115,7 @@ int main(void) MFREE(mat); MFREE(rng); + DESTROY_TIMER(t); return EXIT_SUCCESS; ERROR: return EXIT_FAILURE; diff --git a/src/run_kalign.c b/src/run_kalign.c index e267db6..974dda6 100644 --- a/src/run_kalign.c +++ b/src/run_kalign.c @@ -30,7 +30,7 @@ #include "alignment.h" #include "weave_alignment.h" - +#include "esl_stopwatch.h" #include "misc.h" #include #include "alphabet.h" @@ -439,7 +439,8 @@ int run_kalign(struct parameters* param) START_TIMER(t1); RUNP(map = hirschberg_alignment(msa, ap)); STOP_TIMER(t1); - LOG_MSG("Done in %f sec.", GET_TIMING(t1)); + GET_TIMING(t1); + //LOG_MSG("Done in %f sec.", GET_TIMING(t1)); /* set to aligned */ msa->aligned = ALN_STATUS_ALIGNED; @@ -459,6 +460,7 @@ int run_kalign(struct parameters* param) free_msa(msa); free_ap(ap); + DESTROY_TIMER(t1); return OK; ERROR: free_msa(tmp_msa); diff --git a/src/rwalign.c b/src/rwalign.c index 255f72b..a923b5a 100644 --- a/src/rwalign.c +++ b/src/rwalign.c @@ -23,6 +23,7 @@ #include "global.h" #include "msa.h" #include "alphabet.h" +#include "esl_stopwatch.h" struct in_line{ char* line; @@ -172,6 +173,7 @@ struct msa* read_input(char* infile,struct msa* msa) } } + DECLARE_TIMER(timer); START_TIMER(timer); @@ -202,7 +204,9 @@ struct msa* read_input(char* infile,struct msa* msa) RUN(set_sip_nsip(msa)); free_in_buffer(b); STOP_TIMER(timer); - LOG_MSG("Done reading input sequences in %f seconds.", GET_TIMING(timer)); + GET_TIMING(timer); + DESTROY_TIMER(timer); + //LOG_MSG("Done reading input sequences in %f seconds.", GET_TIMING(timer)); return msa; ERROR: free_msa(msa); diff --git a/src/tldevel.h b/src/tldevel.h index 20f8693..4f97ef7 100644 --- a/src/tldevel.h +++ b/src/tldevel.h @@ -516,12 +516,12 @@ ALLOC_2D_ARRAY_DEF(double); #define LOGSUM_SIZE 1600000 #define SCALE 100000.0 - +/* #define DECLARE_TIMER(n) struct timespec ts1_##n; struct timespec ts2_##n; #define START_TIMER(n) clock_gettime(CLOCK_MONOTONIC_RAW, &ts1_##n); #define STOP_TIMER(n) clock_gettime(CLOCK_MONOTONIC_RAW, &ts2_##n); #define GET_TIMING(n) (double)(ts2_##n.tv_sec - ts1_##n.tv_sec) + ((double) ts2_##n.tv_nsec - ts1_##n.tv_nsec) / 1000000000.0 - +*/ #define DECLARE_CHK(n,dir) struct checkpoint* chk_##n = NULL; RUNP( chk_##n = init_checkpoint(TOSTRING(n),dir));