diff --git a/clint-files.txt b/clint-files.txt index 29fb0908af..d6bf7b8807 100644 --- a/clint-files.txt +++ b/clint-files.txt @@ -50,3 +50,5 @@ src/nvim/os/channel.c src/nvim/os/channel.h src/nvim/tempfile.c src/nvim/tempfile.h +src/nvim/profile.c +src/nvim/profile.h diff --git a/src/nvim/CMakeLists.txt b/src/nvim/CMakeLists.txt index 4a23e76a1c..c38b18114d 100644 --- a/src/nvim/CMakeLists.txt +++ b/src/nvim/CMakeLists.txt @@ -45,6 +45,8 @@ set(CONV_SRCS map.c memory.c misc2.c + map.c + profile.c os/env.c os/event.c os/job.c diff --git a/src/nvim/assert.h b/src/nvim/assert.h new file mode 100644 index 0000000000..3a900aca65 --- /dev/null +++ b/src/nvim/assert.h @@ -0,0 +1,78 @@ +#ifndef NVIM_ASSERT_H +#define NVIM_ASSERT_H + +// support static asserts (aka compile-time asserts) + +// some compilers don't properly support short-circuiting apparently, giving +// ugly syntax errors when using things like defined(__clang__) && +// defined(__has_feature) && __has_feature(...). Therefore we define Clang's +// __has_feature and __has_extension macro's before referring to them. +#ifndef __has_feature + #define __has_feature(x) 0 +#endif + +#ifndef __has_extension + #define __has_extension __has_feature +#endif + +/// STATIC_ASSERT(condition, message) - assert at compile time if !cond +/// +/// example: +/// STATIC_ASSERT(sizeof(void *) == 8, "need 64-bits mode"); + +// define STATIC_ASSERT as C11's _Static_assert whenever either C11 mode is +// detected or the compiler is known to support it. Note that Clang in C99 +// mode defines __has_feature(c_static_assert) as false and +// __has_extension(c_static_assert) as true. Meaning it does support it, but +// warns. A similar thing goes for gcc, which warns when it's not compiling +// as C11 but does support _Static_assert since 4.6. Since we prefer the +// clearer messages we get from _Static_assert, we suppress the warnings +// temporarily. + +// the easiest case, when the mode is C11 (generic compiler) or Clang +// advertises explicit support for c_static_assert, meaning it won't warn. +#if __STDC_VERSION__ >= 201112L || __has_feature(c_static_assert) + #define STATIC_ASSERT(cond, msg) _Static_assert(cond, msg) +// if we're dealing with gcc >= 4.6 in C99 mode, we can still use +// _Static_assert but we need to suppress warnings, this is pretty ugly. +#elif (!defined(__clang__) && !defined(__INTEL_COMPILER)) && \ + (__GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ >= 6)) + #define STATIC_ASSERT(cond, msg) \ + _Pragma("GCC diagnostic push") \ + _Pragma("GCC diagnostic ignored \"-pedantic\"") \ + _Static_assert(cond, msg); \ + _Pragma("GCC diagnostic pop") \ + +// the same goes for clang in C99 mode, but we suppress a different warning +#elif defined(__clang__) && __has_extension(c_static_assert) + #define STATIC_ASSERT(cond, msg) \ + _Pragma("clang diagnostic push") \ + _Pragma("clang diagnostic ignored \"-Wc11-extensions\"") \ + _Static_assert(cond, msg); \ + _Pragma("clang diagnostic pop") \ + +// TODO(aktau): verify that this works, don't have MSVC on hand. +#elif _MSC_VER >= 1600 + #define STATIC_ASSERT(cond, msg) static_assert(cond, msg) + +// fallback for compilers that don't support _Static_assert or static_assert +// not as pretty but gets the job done. Credit goes to Pádraig Brady and +// contributors. +#else + #define ASSERT_CONCAT_(a, b) a##b + #define ASSERT_CONCAT(a, b) ASSERT_CONCAT_(a, b) + // These can't be used after statements in c89. + #ifdef __COUNTER__ + #define STATIC_ASSERT(e,m) \ + { enum { ASSERT_CONCAT(static_assert_, __COUNTER__) = 1/(!!(e)) }; } + #else + // This can't be used twice on the same line so ensure if using in headers + // that the headers are not included twice (by wrapping in #ifndef...#endif) + // Note it doesn't cause an issue when used on same line of separate modules + // compiled with gcc -combine -fwhole-program. + #define STATIC_ASSERT(e,m) \ + { enum { ASSERT_CONCAT(assert_line_, __LINE__) = 1/(!!(e)) }; } + #endif +#endif + +#endif // NVIM_ASSERT_H diff --git a/src/nvim/buffer_defs.h b/src/nvim/buffer_defs.h index 50f5d03f94..9d81388a3c 100644 --- a/src/nvim/buffer_defs.h +++ b/src/nvim/buffer_defs.h @@ -17,6 +17,8 @@ #include "nvim/hashtab.h" // for dict_T #include "nvim/eval_defs.h" +// for proftime_T +#include "nvim/profile.h" /* * Flags for w_valid. diff --git a/src/nvim/eval.c b/src/nvim/eval.c index 3459b5c4a0..d82f71b836 100644 --- a/src/nvim/eval.c +++ b/src/nvim/eval.c @@ -18,6 +18,7 @@ #include #include +#include "nvim/assert.h" #include "nvim/vim.h" #include "nvim/ascii.h" #ifdef HAVE_LOCALE_H @@ -59,6 +60,7 @@ #include "nvim/os_unix.h" #include "nvim/path.h" #include "nvim/popupmnu.h" +#include "nvim/profile.h" #include "nvim/quickfix.h" #include "nvim/regexp.h" #include "nvim/screen.h" @@ -1209,8 +1211,10 @@ void prof_child_enter(proftime_T *tm /* place to store waittime */ { funccall_T *fc = current_funccal; - if (fc != NULL && fc->func->uf_profiling) - profile_start(&fc->prof_child); + if (fc != NULL && fc->func->uf_profiling) { + fc->prof_child = profile_start(); + } + script_prof_save(tm); } @@ -1224,10 +1228,13 @@ void prof_child_exit(proftime_T *tm /* where waittime was stored */ funccall_T *fc = current_funccal; if (fc != NULL && fc->func->uf_profiling) { - profile_end(&fc->prof_child); - profile_sub_wait(tm, &fc->prof_child); /* don't count waiting time */ - profile_add(&fc->func->uf_tm_children, &fc->prof_child); - profile_add(&fc->func->uf_tml_children, &fc->prof_child); + fc->prof_child = profile_end(fc->prof_child); + // don't count waiting time + fc->prof_child = profile_sub_wait(*tm, fc->prof_child); + fc->func->uf_tm_children = + profile_add(fc->func->uf_tm_children, fc->prof_child); + fc->func->uf_tml_children = + profile_add(fc->func->uf_tml_children, fc->prof_child); } script_prof_restore(tm); } @@ -11646,66 +11653,101 @@ static void f_readfile(typval_T *argvars, typval_T *rettv) } -/* - * Convert a List to proftime_T. - * Return FAIL when there is something wrong. - */ -static int list2proftime(typval_T *arg, proftime_T *tm) +/// list2proftime - convert a List to proftime_T +/// +/// @param arg The input list, must be of type VAR_LIST and have +/// exactly 2 items +/// @param[out] tm The proftime_T representation of `arg` +/// @return OK In case of success, FAIL in case of error +static int list2proftime(typval_T *arg, proftime_T *tm) FUNC_ATTR_NONNULL_ALL { - long n1, n2; - int error = FALSE; - - if (arg->v_type != VAR_LIST || arg->vval.v_list == NULL - || arg->vval.v_list->lv_len != 2) + if (arg->v_type != VAR_LIST + || arg->vval.v_list == NULL + || arg->vval.v_list->lv_len != 2) { return FAIL; - n1 = list_find_nr(arg->vval.v_list, 0L, &error); - n2 = list_find_nr(arg->vval.v_list, 1L, &error); - tm->tv_sec = n1; - tm->tv_usec = n2; - return error ? FAIL : OK; + } + + int error = false; + varnumber_T n1 = list_find_nr(arg->vval.v_list, 0L, &error); + varnumber_T n2 = list_find_nr(arg->vval.v_list, 1L, &error); + if (error) { + return FAIL; + } + + // in f_reltime() we split up the 64-bit proftime_T into two 32-bit + // values, now we combine them again. + union { + struct { varnumber_T low, high; } split; + proftime_T prof; + } u = { .split.high = n1, .split.low = n2 }; + + *tm = u.prof; + + return OK; } -/* - * "reltime()" function - */ -static void f_reltime(typval_T *argvars, typval_T *rettv) +/// f_reltime - return an item that represents a time value +/// +/// @param[out] rettv Without an argument it returns the current time. With +/// one argument it returns the time passed since the argument. +/// With two arguments it returns the time passed between +/// the two arguments. +static void f_reltime(typval_T *argvars, typval_T *rettv) FUNC_ATTR_NONNULL_ALL { proftime_T res; proftime_T start; if (argvars[0].v_type == VAR_UNKNOWN) { - /* No arguments: get current time. */ - profile_start(&res); + // no arguments: get current time. + res = profile_start(); } else if (argvars[1].v_type == VAR_UNKNOWN) { - if (list2proftime(&argvars[0], &res) == FAIL) + if (list2proftime(&argvars[0], &res) == FAIL) { return; - profile_end(&res); + } + res = profile_end(res); } else { - /* Two arguments: compute the difference. */ + // two arguments: compute the difference. if (list2proftime(&argvars[0], &start) == FAIL - || list2proftime(&argvars[1], &res) == FAIL) + || list2proftime(&argvars[1], &res) == FAIL) { return; - profile_sub(&res, &start); + } + res = profile_sub(res, start); } + // we have to store the 64-bit proftime_T inside of a list of int's + // (varnumber_T is defined as int). For all our supported platforms, int's + // are at least 32-bits wide. So we'll use two 32-bit values to store it. + union { + struct { varnumber_T low, high; } split; + proftime_T prof; + } u = { .prof = res }; + + // statically assert that the union type conv will provide the correct + // results, if varnumber_T or proftime_T change, the union cast will need + // to be revised. + STATIC_ASSERT(sizeof(u.prof) == sizeof(u) && sizeof(u.split) == sizeof(u), + "type punning will produce incorrect results on this platform"); + rettv_list_alloc(rettv); - long n1 = res.tv_sec; - long n2 = res.tv_usec; - list_append_number(rettv->vval.v_list, (varnumber_T)n1); - list_append_number(rettv->vval.v_list, (varnumber_T)n2); + list_append_number(rettv->vval.v_list, u.split.high); + list_append_number(rettv->vval.v_list, u.split.low); } -/* - * "reltimestr()" function - */ +/// f_reltimestr - return a string that represents the value of {time} +/// +/// @return The string representation of the argument, the format is the +/// number of seconds followed by a dot, followed by the number +/// of microseconds. static void f_reltimestr(typval_T *argvars, typval_T *rettv) + FUNC_ATTR_NONNULL_ALL { proftime_T tm; rettv->v_type = VAR_STRING; rettv->vval.v_string = NULL; - if (list2proftime(&argvars[0], &tm) == OK) - rettv->vval.v_string = vim_strsave((char_u *)profile_msg(&tm)); + if (list2proftime(&argvars[0], &tm) == OK) { + rettv->vval.v_string = (char_u *) xstrdup(profile_msg(tm)); + } } /* @@ -12134,7 +12176,7 @@ static int search_cmn(typval_T *argvars, pos_T *match_pos, int *flagsp) } /* Set the time limit, if there is one. */ - profile_setlimit(time_limit, &tm); + tm = profile_setlimit(time_limit); /* * This function does not accept SP_REPEAT and SP_RETCOUNT flags. @@ -12426,7 +12468,7 @@ do_searchpair ( p_cpo = empty_option; /* Set the time limit, if there is one. */ - profile_setlimit(time_limit, &tm); + tm = profile_setlimit(time_limit); /* Make two search patterns: start/end (pat2, for in nested pairs) and * start/middle/end (pat3, for the top pair). */ @@ -17435,8 +17477,8 @@ static void func_do_profile(ufunc_T *fp) if (len == 0) len = 1; /* avoid getting error for allocating zero bytes */ fp->uf_tm_count = 0; - profile_zero(&fp->uf_tm_self); - profile_zero(&fp->uf_tm_total); + fp->uf_tm_self = profile_zero(); + fp->uf_tm_total = profile_zero(); if (fp->uf_tml_count == NULL) { fp->uf_tml_count = xcalloc(len, sizeof(int)); @@ -17488,8 +17530,8 @@ void func_dump_profile(FILE *fd) fprintf(fd, "Called 1 time\n"); else fprintf(fd, "Called %d times\n", fp->uf_tm_count); - fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total)); - fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self)); + fprintf(fd, "Total time: %s\n", profile_msg(fp->uf_tm_total)); + fprintf(fd, " Self time: %s\n", profile_msg(fp->uf_tm_self)); fprintf(fd, "\n"); fprintf(fd, "count total (s) self (s)\n"); @@ -17556,14 +17598,14 @@ static void prof_func_line( { if (count > 0) { fprintf(fd, "%5d ", count); - if (prefer_self && profile_equal(total, self)) + if (prefer_self && profile_equal(*total, *self)) fprintf(fd, " "); else - fprintf(fd, "%s ", profile_msg(total)); - if (!prefer_self && profile_equal(total, self)) + fprintf(fd, "%s ", profile_msg(*total)); + if (!prefer_self && profile_equal(*total, *self)) fprintf(fd, " "); else - fprintf(fd, "%s ", profile_msg(self)); + fprintf(fd, "%s ", profile_msg(*self)); } else fprintf(fd, " "); } @@ -17573,11 +17615,9 @@ static void prof_func_line( */ static int prof_total_cmp(const void *s1, const void *s2) { - ufunc_T *p1, *p2; - - p1 = *(ufunc_T **)s1; - p2 = *(ufunc_T **)s2; - return profile_cmp(&p1->uf_tm_total, &p2->uf_tm_total); + ufunc_T *p1 = *(ufunc_T **)s1; + ufunc_T *p2 = *(ufunc_T **)s2; + return profile_cmp(p1->uf_tm_total, p2->uf_tm_total); } /* @@ -17585,11 +17625,9 @@ static int prof_total_cmp(const void *s1, const void *s2) */ static int prof_self_cmp(const void *s1, const void *s2) { - ufunc_T *p1, *p2; - - p1 = *(ufunc_T **)s1; - p2 = *(ufunc_T **)s2; - return profile_cmp(&p1->uf_tm_self, &p2->uf_tm_self); + ufunc_T *p1 = *(ufunc_T **)s1; + ufunc_T *p2 = *(ufunc_T **)s2; + return profile_cmp(p1->uf_tm_self, p2->uf_tm_self); } @@ -18018,8 +18056,8 @@ call_user_func ( if (fp->uf_profiling || (fc->caller != NULL && fc->caller->func->uf_profiling)) { ++fp->uf_tm_count; - profile_start(&call_start); - profile_zero(&fp->uf_tm_children); + call_start = profile_start(); + fp->uf_tm_children = profile_zero(); } script_prof_save(&wait_start); } @@ -18046,13 +18084,16 @@ call_user_func ( if (do_profiling == PROF_YES && (fp->uf_profiling || (fc->caller != NULL && fc->caller->func->uf_profiling))) { - profile_end(&call_start); - profile_sub_wait(&wait_start, &call_start); - profile_add(&fp->uf_tm_total, &call_start); - profile_self(&fp->uf_tm_self, &call_start, &fp->uf_tm_children); + call_start = profile_end(call_start); + call_start = profile_sub_wait(wait_start, call_start); + fp->uf_tm_total = profile_add(fp->uf_tm_total, call_start); + fp->uf_tm_self = profile_self(fp->uf_tm_self, call_start, + fp->uf_tm_children); if (fc->caller != NULL && fc->caller->func->uf_profiling) { - profile_add(&fc->caller->func->uf_tm_children, &call_start); - profile_add(&fc->caller->func->uf_tml_children, &call_start); + fc->caller->func->uf_tm_children = + profile_add(fc->caller->func->uf_tm_children, call_start); + fc->caller->func->uf_tml_children = + profile_add(fc->caller->func->uf_tml_children, call_start); } } @@ -18415,9 +18456,9 @@ void func_line_start(void *cookie) while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL) --fp->uf_tml_idx; fp->uf_tml_execed = FALSE; - profile_start(&fp->uf_tml_start); - profile_zero(&fp->uf_tml_children); - profile_get_wait(&fp->uf_tml_wait); + fp->uf_tml_start = profile_start(); + fp->uf_tml_children = profile_zero(); + fp->uf_tml_wait = profile_get_wait(); } } @@ -18444,11 +18485,13 @@ void func_line_end(void *cookie) if (fp->uf_profiling && fp->uf_tml_idx >= 0) { if (fp->uf_tml_execed) { ++fp->uf_tml_count[fp->uf_tml_idx]; - profile_end(&fp->uf_tml_start); - profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start); - profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start); - profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start, - &fp->uf_tml_children); + fp->uf_tml_start = profile_end(fp->uf_tml_start); + fp->uf_tml_start = profile_sub_wait(fp->uf_tml_wait, fp->uf_tml_start); + fp->uf_tml_total[fp->uf_tml_idx] = + profile_add(fp->uf_tml_total[fp->uf_tml_idx], fp->uf_tml_start); + fp->uf_tml_self[fp->uf_tml_idx] = + profile_self(fp->uf_tml_self[fp->uf_tml_idx], fp->uf_tml_start, + fp->uf_tml_children); } fp->uf_tml_idx = -1; } diff --git a/src/nvim/eval.h b/src/nvim/eval.h index 66953faeb7..2f36a46f70 100644 --- a/src/nvim/eval.h +++ b/src/nvim/eval.h @@ -1,6 +1,8 @@ #ifndef NVIM_EVAL_H #define NVIM_EVAL_H +#include "nvim/profile.h" + /* Defines for Vim variables. These must match vimvars[] in eval.c! */ enum { VV_COUNT, diff --git a/src/nvim/ex_cmds2.c b/src/nvim/ex_cmds2.c index 85a9e9315a..c87f134ea2 100644 --- a/src/nvim/ex_cmds2.c +++ b/src/nvim/ex_cmds2.c @@ -50,6 +50,7 @@ #include "nvim/term.h" #include "nvim/undo.h" #include "nvim/window.h" +#include "nvim/profile.h" #include "nvim/os/os.h" #include "nvim/os/shell.h" #include "nvim/os/fs_defs.h" @@ -744,192 +745,15 @@ void dbg_breakpoint(char_u *name, linenr_T lnum) debug_breakpoint_lnum = lnum; } - -/* - * Store the current time in "tm". - */ -void profile_start(proftime_T *tm) -{ - gettimeofday(tm, NULL); -} - -/* - * Compute the elapsed time from "tm" till now and store in "tm". - */ -void profile_end(proftime_T *tm) -{ - proftime_T now; - - gettimeofday(&now, NULL); - tm->tv_usec = now.tv_usec - tm->tv_usec; - tm->tv_sec = now.tv_sec - tm->tv_sec; - if (tm->tv_usec < 0) { - tm->tv_usec += 1000000; - --tm->tv_sec; - } -} - -/* - * Subtract the time "tm2" from "tm". - */ -void profile_sub(proftime_T *tm, proftime_T *tm2) -{ - tm->tv_usec -= tm2->tv_usec; - tm->tv_sec -= tm2->tv_sec; - if (tm->tv_usec < 0) { - tm->tv_usec += 1000000; - --tm->tv_sec; - } -} - -/* - * Return a string that represents the time in "tm". - * Uses a static buffer! - */ -char * profile_msg(proftime_T *tm) -{ - static char buf[50]; - - sprintf(buf, "%3ld.%06ld", (long)tm->tv_sec, (long)tm->tv_usec); - return buf; -} - -/* - * Put the time "msec" past now in "tm". - */ -void profile_setlimit(long msec, proftime_T *tm) -{ - if (msec <= 0) /* no limit */ - profile_zero(tm); - else { - long usec; - - gettimeofday(tm, NULL); - usec = (long)tm->tv_usec + (long)msec * 1000; - tm->tv_usec = usec % 1000000L; - tm->tv_sec += usec / 1000000L; - } -} - -/* - * Return TRUE if the current time is past "tm". - */ -int profile_passed_limit(proftime_T *tm) -{ - proftime_T now; - - if (tm->tv_sec == 0) /* timer was not set */ - return FALSE; - gettimeofday(&now, NULL); - return now.tv_sec > tm->tv_sec - || (now.tv_sec == tm->tv_sec && now.tv_usec > tm->tv_usec); -} - -/* - * Set the time in "tm" to zero. - */ -void profile_zero(proftime_T *tm) -{ - tm->tv_usec = 0; - tm->tv_sec = 0; -} - - -#include - -/* - * Divide the time "tm" by "count" and store in "tm2". - */ -void profile_divide(proftime_T *tm, int count, proftime_T *tm2) -{ - if (count == 0) - profile_zero(tm2); - else { - double usec = (tm->tv_sec * 1000000.0 + tm->tv_usec) / count; - - tm2->tv_sec = floor(usec / 1000000.0); - tm2->tv_usec = round(usec - (tm2->tv_sec * 1000000.0)); - } -} - -/* - * Functions for profiling. - */ -static proftime_T prof_wait_time; - -/* - * Add the time "tm2" to "tm". - */ -void profile_add(proftime_T *tm, proftime_T *tm2) -{ - tm->tv_usec += tm2->tv_usec; - tm->tv_sec += tm2->tv_sec; - if (tm->tv_usec >= 1000000) { - tm->tv_usec -= 1000000; - ++tm->tv_sec; - } -} - -/* - * Add the "self" time from the total time and the children's time. - */ -void profile_self(proftime_T *self, proftime_T *total, proftime_T *children) -{ - /* Check that the result won't be negative. Can happen with recursive - * calls. */ - if (total->tv_sec < children->tv_sec - || (total->tv_sec == children->tv_sec - && total->tv_usec <= children->tv_usec)) - return; - profile_add(self, total); - profile_sub(self, children); -} - -/* - * Get the current waittime. - */ -void profile_get_wait(proftime_T *tm) -{ - *tm = prof_wait_time; -} - -/* - * Subtract the passed waittime since "tm" from "tma". - */ -void profile_sub_wait(proftime_T *tm, proftime_T *tma) -{ - proftime_T tm3 = prof_wait_time; - - profile_sub(&tm3, tm); - profile_sub(tma, &tm3); -} - -/* - * Return TRUE if "tm1" and "tm2" are equal. - */ -int profile_equal(proftime_T *tm1, proftime_T *tm2) -{ - return tm1->tv_usec == tm2->tv_usec && tm1->tv_sec == tm2->tv_sec; -} - -/* - * Return <0, 0 or >0 if "tm1" < "tm2", "tm1" == "tm2" or "tm1" > "tm2" - */ -int profile_cmp(const proftime_T *tm1, const proftime_T *tm2) -{ - if (tm1->tv_sec == tm2->tv_sec) - return tm2->tv_usec - tm1->tv_usec; - return tm2->tv_sec - tm1->tv_sec; -} - static char_u *profile_fname = NULL; -static proftime_T pause_time; /* * ":profile cmd args" */ void ex_profile(exarg_T *eap) { + static proftime_T pause_time; + char_u *e; int len; @@ -941,18 +765,18 @@ void ex_profile(exarg_T *eap) free(profile_fname); profile_fname = vim_strsave(e); do_profiling = PROF_YES; - profile_zero(&prof_wait_time); + profile_set_wait(profile_zero()); set_vim_var_nr(VV_PROFILING, 1L); } else if (do_profiling == PROF_NONE) EMSG(_("E750: First use \":profile start {fname}\"")); else if (STRCMP(eap->arg, "pause") == 0) { if (do_profiling == PROF_YES) - profile_start(&pause_time); + pause_time = profile_start(); do_profiling = PROF_PAUSED; } else if (STRCMP(eap->arg, "continue") == 0) { if (do_profiling == PROF_PAUSED) { - profile_end(&pause_time); - profile_add(&prof_wait_time, &pause_time); + pause_time = profile_end(pause_time); + profile_set_wait(profile_add(profile_get_wait(), pause_time)); } do_profiling = PROF_YES; } else { @@ -1048,8 +872,8 @@ void profile_dump(void) static void script_do_profile(scriptitem_T *si) { si->sn_pr_count = 0; - profile_zero(&si->sn_pr_total); - profile_zero(&si->sn_pr_self); + si->sn_pr_total = profile_zero(); + si->sn_pr_self = profile_zero(); ga_init(&si->sn_prl_ga, sizeof(sn_prl_T), 100); si->sn_prl_idx = -1; @@ -1069,9 +893,9 @@ void script_prof_save( if (current_SID > 0 && current_SID <= script_items.ga_len) { si = &SCRIPT_ITEM(current_SID); if (si->sn_prof_on && si->sn_pr_nest++ == 0) - profile_start(&si->sn_pr_child); + si->sn_pr_child = profile_start(); } - profile_get_wait(tm); + *tm = profile_get_wait(); } /* @@ -1084,10 +908,11 @@ void script_prof_restore(proftime_T *tm) if (current_SID > 0 && current_SID <= script_items.ga_len) { si = &SCRIPT_ITEM(current_SID); if (si->sn_prof_on && --si->sn_pr_nest == 0) { - profile_end(&si->sn_pr_child); - profile_sub_wait(tm, &si->sn_pr_child); /* don't count wait time */ - profile_add(&si->sn_pr_children, &si->sn_pr_child); - profile_add(&si->sn_prl_children, &si->sn_pr_child); + si->sn_pr_child = profile_end(si->sn_pr_child); + // don't count wait time + si->sn_pr_child = profile_sub_wait(*tm, si->sn_pr_child); + si->sn_pr_children = profile_add(si->sn_pr_children, si->sn_pr_child); + si->sn_prl_children = profile_add(si->sn_prl_children, si->sn_pr_child); } } } @@ -1099,7 +924,7 @@ static proftime_T inchar_time; */ void prof_inchar_enter(void) { - profile_start(&inchar_time); + inchar_time = profile_start(); } /* @@ -1107,8 +932,8 @@ void prof_inchar_enter(void) */ void prof_inchar_exit(void) { - profile_end(&inchar_time); - profile_add(&prof_wait_time, &inchar_time); + inchar_time = profile_end(inchar_time); + profile_set_wait(profile_add(profile_get_wait(), inchar_time)); } /* @@ -1128,8 +953,8 @@ static void script_dump_profile(FILE *fd) fprintf(fd, "Sourced 1 time\n"); else fprintf(fd, "Sourced %d times\n", si->sn_pr_count); - fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total)); - fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self)); + fprintf(fd, "Total time: %s\n", profile_msg(si->sn_pr_total)); + fprintf(fd, " Self time: %s\n", profile_msg(si->sn_pr_self)); fprintf(fd, "\n"); fprintf(fd, "count total (s) self (s)\n"); @@ -1143,11 +968,11 @@ static void script_dump_profile(FILE *fd) pp = &PRL_ITEM(si, i); if (pp->snp_count > 0) { fprintf(fd, "%5d ", pp->snp_count); - if (profile_equal(&pp->sn_prl_total, &pp->sn_prl_self)) + if (profile_equal(pp->sn_prl_total, pp->sn_prl_self)) fprintf(fd, " "); else - fprintf(fd, "%s ", profile_msg(&pp->sn_prl_total)); - fprintf(fd, "%s ", profile_msg(&pp->sn_prl_self)); + fprintf(fd, "%s ", profile_msg(pp->sn_prl_total)); + fprintf(fd, "%s ", profile_msg(pp->sn_prl_self)); } else fprintf(fd, " "); fprintf(fd, "%s", IObuff); @@ -2610,8 +2435,8 @@ do_source ( } if (si->sn_prof_on) { ++si->sn_pr_count; - profile_start(&si->sn_pr_start); - profile_zero(&si->sn_pr_children); + si->sn_pr_start = profile_start(); + si->sn_pr_children = profile_zero(); } } @@ -2626,11 +2451,11 @@ do_source ( /* Get "si" again, "script_items" may have been reallocated. */ si = &SCRIPT_ITEM(current_SID); if (si->sn_prof_on) { - profile_end(&si->sn_pr_start); - profile_sub_wait(&wait_start, &si->sn_pr_start); - profile_add(&si->sn_pr_total, &si->sn_pr_start); - profile_self(&si->sn_pr_self, &si->sn_pr_start, - &si->sn_pr_children); + si->sn_pr_start = profile_end(si->sn_pr_start); + si->sn_pr_start = profile_sub_wait(wait_start, si->sn_pr_start); + si->sn_pr_total = profile_add(si->sn_pr_total, si->sn_pr_start); + si->sn_pr_self = profile_self(si->sn_pr_self, si->sn_pr_start, + si->sn_pr_children); } } @@ -2949,14 +2774,14 @@ void script_line_start(void) /* Zero counters for a line that was not used before. */ pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len); pp->snp_count = 0; - profile_zero(&pp->sn_prl_total); - profile_zero(&pp->sn_prl_self); + pp->sn_prl_total = profile_zero(); + pp->sn_prl_self = profile_zero(); ++si->sn_prl_ga.ga_len; } si->sn_prl_execed = FALSE; - profile_start(&si->sn_prl_start); - profile_zero(&si->sn_prl_children); - profile_get_wait(&si->sn_prl_wait); + si->sn_prl_start = profile_start(); + si->sn_prl_children = profile_zero(); + si->sn_prl_wait = profile_get_wait(); } } @@ -2990,11 +2815,11 @@ void script_line_end(void) if (si->sn_prl_execed) { pp = &PRL_ITEM(si, si->sn_prl_idx); ++pp->snp_count; - profile_end(&si->sn_prl_start); - profile_sub_wait(&si->sn_prl_wait, &si->sn_prl_start); - profile_add(&pp->sn_prl_total, &si->sn_prl_start); - profile_self(&pp->sn_prl_self, &si->sn_prl_start, - &si->sn_prl_children); + si->sn_prl_start = profile_end(si->sn_prl_start); + si->sn_prl_start = profile_sub_wait(si->sn_prl_wait, si->sn_prl_start); + pp->sn_prl_total = profile_add(pp->sn_prl_total, si->sn_prl_start); + pp->sn_prl_self = profile_self(pp->sn_prl_self, si->sn_prl_start, + si->sn_prl_children); } si->sn_prl_idx = -1; } diff --git a/src/nvim/ex_getln.c b/src/nvim/ex_getln.c index e8e2f61679..67748fa164 100644 --- a/src/nvim/ex_getln.c +++ b/src/nvim/ex_getln.c @@ -1396,7 +1396,7 @@ cmdline_changed: out_flush(); ++emsg_off; /* So it doesn't beep if bad expr */ /* Set the time limit to half a second. */ - profile_setlimit(500L, &tm); + tm = profile_setlimit(500L); i = do_search(NULL, firstc, ccline.cmdbuff, count, SEARCH_KEEP + SEARCH_OPT + SEARCH_NOOF + SEARCH_PEEK, &tm diff --git a/src/nvim/os/time.c b/src/nvim/os/time.c index 90a17aa513..00ffccfaa8 100644 --- a/src/nvim/os/time.c +++ b/src/nvim/os/time.c @@ -22,6 +22,15 @@ void time_init(void) uv_cond_init(&delay_cond); } +/// Obtain a high-resolution timer value +/// +/// @return a timer value, not related to the time of day and not subject +/// to clock drift. The value is expressed in nanoseconds. +uint64_t os_hrtime(void) +{ + return uv_hrtime(); +} + /// Sleeps for a certain amount of milliseconds /// /// @param milliseconds Number of milliseconds to sleep diff --git a/src/nvim/profile.c b/src/nvim/profile.c new file mode 100644 index 0000000000..6a77d42205 --- /dev/null +++ b/src/nvim/profile.c @@ -0,0 +1,184 @@ +#include +#include +#include + +#include "nvim/profile.h" +#include "nvim/os/time.h" +#include "nvim/func_attr.h" + +#ifdef INCLUDE_GENERATED_DECLARATIONS +# include "profile.c.generated.h" +#endif + +/// functions for profiling + +static proftime_T prof_wait_time; + +/// profile_start - return the current time +/// +/// @return the current time +proftime_T profile_start(void) FUNC_ATTR_WARN_UNUSED_RESULT +{ + return os_hrtime(); +} + +/// profile_end - compute the time elapsed +/// +/// @return the elapsed time from `tm` until now. +proftime_T profile_end(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT +{ + return os_hrtime() - tm; +} + +/// profile_msg - return a string that represents the time in `tm` +/// +/// @warning Do not modify or free this string, not multithread-safe. +/// +/// @param tm The time to be represented +/// @return a static string representing `tm` in the +/// form "seconds.microseconds". +const char *profile_msg(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT +{ + static char buf[50]; + + snprintf(buf, sizeof(buf), "%10.6lf", (double)tm / 1000000000.0); + + return buf; +} + +/// profile_setlimit - return the time `msec` into the future +/// +/// @param msec milliseconds, the maximum number of milliseconds is +/// (2^63 / 10^6) - 1 = 9.223372e+12. +/// @return if msec > 0, returns the time msec past now. Otherwise returns +/// the zero time. +proftime_T profile_setlimit(int64_t msec) FUNC_ATTR_WARN_UNUSED_RESULT +{ + if (msec <= 0) { + // no limit + return profile_zero(); + } + + assert(msec <= (INT64_MAX / 1000000LL) - 1); + + proftime_T nsec = (proftime_T) msec * 1000000ULL; + return os_hrtime() + nsec; +} + +/// profile_passed_limit - check if current time has passed `tm` +/// +/// @return true if the current time is past `tm`, false if not or if the +/// timer was not set. +bool profile_passed_limit(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT +{ + if (tm == 0) { + // timer was not set + return false; + } + + return profile_cmp(os_hrtime(), tm) < 0; +} + +/// profile_zero - obtain the zero time +/// +/// @return the zero time +proftime_T profile_zero(void) FUNC_ATTR_CONST +{ + return 0; +} + +/// profile_divide - divide the time `tm` by `count`. +/// +/// @return 0 if count <= 0, otherwise tm / count +proftime_T profile_divide(proftime_T tm, int count) FUNC_ATTR_CONST +{ + if (count <= 0) { + return profile_zero(); + } + + return (proftime_T) round((double) tm / (double) count); +} + +/// profile_add - add the time `tm2` to `tm1` +/// +/// @return `tm1` + `tm2` +proftime_T profile_add(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST +{ + return tm1 + tm2; +} + +/// profile_sub - subtract `tm2` from `tm1` +/// +/// @return `tm1` - `tm2` +proftime_T profile_sub(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST +{ + return tm1 - tm2; +} + +/// profile_self - add the `self` time from the total time and the +/// children's time +/// +/// @return if `total` <= `children`, then self, otherwise `self` + `total` - +/// `children` +proftime_T profile_self(proftime_T self, proftime_T total, proftime_T children) + FUNC_ATTR_CONST +{ + // check that the result won't be negative, which can happen with + // recursive calls. + if (total <= children) { + return self; + } + + // add the total time to self and subtract the children's time from self + return profile_sub(profile_add(self, total), children); +} + +/// profile_get_wait - get the current waittime +/// +/// @return the current waittime +proftime_T profile_get_wait(void) FUNC_ATTR_PURE +{ + return prof_wait_time; +} + +/// profile_set_wait - set the current waittime +void profile_set_wait(proftime_T wait) +{ + prof_wait_time = wait; +} + +/// profile_sub_wait - subtract the passed waittime since `tm` +/// +/// @return `tma` - (waittime - `tm`) +proftime_T profile_sub_wait(proftime_T tm, proftime_T tma) FUNC_ATTR_PURE +{ + proftime_T tm3 = profile_sub(profile_get_wait(), tm); + return profile_sub(tma, tm3); +} + +/// profile_equal - check if `tm1` is equal to `tm2` +/// +/// @return true if `tm1` == `tm2` +bool profile_equal(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST +{ + return tm1 == tm2; +} + +/// sgn64 - calculates the sign of a 64-bit integer +/// +/// @return -1, 0, or +1 +static inline int sgn64(int64_t x) FUNC_ATTR_CONST +{ + return (int) ((x > 0) - (x < 0)); +} + +/// profile_cmp - compare profiling times +/// +/// Only guarantees correct results if both input times are not more than +/// 150 years apart. +/// +/// @return <0, 0 or >0 if `tm2` < `tm1`, `tm2` == `tm1` or `tm2` > `tm1` +int profile_cmp(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST +{ + return sgn64((int64_t)(tm2 - tm1)); +} diff --git a/src/nvim/profile.h b/src/nvim/profile.h new file mode 100644 index 0000000000..26d1ebe3a2 --- /dev/null +++ b/src/nvim/profile.h @@ -0,0 +1,13 @@ +#ifndef NVIM_PROFILE_H +#define NVIM_PROFILE_H + +#include +#include + +typedef uint64_t proftime_T; + +#ifdef INCLUDE_GENERATED_DECLARATIONS +# include "profile.h.generated.h" +#endif + +#endif // NVIM_PROFILE_H diff --git a/src/nvim/regexp.c b/src/nvim/regexp.c index f9f02eac9d..fd1b6116f2 100644 --- a/src/nvim/regexp.c +++ b/src/nvim/regexp.c @@ -3468,7 +3468,7 @@ static long bt_regexec_both(char_u *line, /* Check for timeout once in a twenty times to avoid overhead. */ if (tm != NULL && ++tm_count == 20) { tm_count = 0; - if (profile_passed_limit(tm)) + if (profile_passed_limit(*tm)) break; } } diff --git a/src/nvim/screen.c b/src/nvim/screen.c index 4c4df51eb2..0d0d068b36 100644 --- a/src/nvim/screen.c +++ b/src/nvim/screen.c @@ -5441,7 +5441,7 @@ static void start_search_hl(void) last_pat_prog(&search_hl.rm); search_hl.attr = hl_attr(HLF_L); /* Set the time limit to 'redrawtime'. */ - profile_setlimit(p_rdt, &search_hl.tm); + search_hl.tm = profile_setlimit(p_rdt); } } @@ -5476,7 +5476,7 @@ static void init_search_hl(win_T *wp) cur->hl.lnum = 0; cur->hl.first_lnum = 0; /* Set the time limit to 'redrawtime'. */ - profile_setlimit(p_rdt, &(cur->hl.tm)); + cur->hl.tm = profile_setlimit(p_rdt); cur = cur->next; } search_hl.buf = wp->w_buffer; @@ -5578,7 +5578,7 @@ next_search_hl ( called_emsg = FALSE; for (;; ) { /* Stop searching after passing the time limit. */ - if (profile_passed_limit(&(shl->tm))) { + if (profile_passed_limit(shl->tm)) { shl->lnum = 0; /* no match found in time */ break; } diff --git a/src/nvim/search.c b/src/nvim/search.c index f28f7026b0..5c92ef71a9 100644 --- a/src/nvim/search.c +++ b/src/nvim/search.c @@ -530,7 +530,7 @@ int searchit( ? lnum > stop_lnum : lnum < stop_lnum)) break; /* Stop after passing the "tm" time limit. */ - if (tm != NULL && profile_passed_limit(tm)) + if (tm != NULL && profile_passed_limit(*tm)) break; /* diff --git a/src/nvim/syntax.c b/src/nvim/syntax.c index 96d45f41bf..51aeda7293 100644 --- a/src/nvim/syntax.c +++ b/src/nvim/syntax.c @@ -2856,17 +2856,19 @@ static int syn_regexec(regmmatch_T *rmp, linenr_T lnum, colnr_T col, syn_time_T int r; proftime_T pt; - if (syn_time_on) - profile_start(&pt); + if (syn_time_on) { + pt = profile_start(); + } rmp->rmm_maxcol = syn_buf->b_p_smc; r = vim_regexec_multi(rmp, syn_win, syn_buf, lnum, col, NULL); if (syn_time_on) { - profile_end(&pt); - profile_add(&st->total, &pt); - if (profile_cmp(&pt, &st->slowest) < 0) + pt = profile_end(pt); + st->total = profile_add(st->total, pt); + if (profile_cmp(pt, st->slowest) < 0) { st->slowest = pt; + } ++st->count; if (r > 0) ++st->match; @@ -5630,8 +5632,8 @@ void ex_syntime(exarg_T *eap) static void syn_clear_time(syn_time_T *st) { - profile_zero(&st->total); - profile_zero(&st->slowest); + st->total = profile_zero(); + st->slowest = profile_zero(); st->count = 0; st->match = 0; } @@ -5673,7 +5675,7 @@ static int syn_compare_syntime(const void *v1, const void *v2) const time_entry_T *s1 = v1; const time_entry_T *s2 = v2; - return profile_cmp(&s1->total, &s2->total); + return profile_cmp(s1->total, s2->total); } /* @@ -5684,7 +5686,6 @@ static void syntime_report(void) synpat_T *spp; proftime_T tm; int len; - proftime_T total_total; int total_count = 0; garray_T ga; time_entry_T *p; @@ -5695,18 +5696,18 @@ static void syntime_report(void) } ga_init(&ga, sizeof(time_entry_T), 50); - profile_zero(&total_total); + proftime_T total_total = profile_zero(); for (int idx = 0; idx < curwin->w_s->b_syn_patterns.ga_len; ++idx) { spp = &(SYN_ITEMS(curwin->w_s)[idx]); if (spp->sp_time.count > 0) { p = GA_APPEND_VIA_PTR(time_entry_T, &ga); p->total = spp->sp_time.total; - profile_add(&total_total, &spp->sp_time.total); + total_total = profile_add(total_total, spp->sp_time.total); p->count = spp->sp_time.count; p->match = spp->sp_time.match; total_count += spp->sp_time.count; p->slowest = spp->sp_time.slowest; - profile_divide(&spp->sp_time.total, spp->sp_time.count, &tm); + tm = profile_divide(spp->sp_time.total, spp->sp_time.count); p->average = tm; p->id = spp->sp_syn.id; p->pattern = spp->sp_pattern; @@ -5724,7 +5725,7 @@ static void syntime_report(void) spp = &(SYN_ITEMS(curwin->w_s)[idx]); p = ((time_entry_T *)ga.ga_data) + idx; - MSG_PUTS(profile_msg(&p->total)); + MSG_PUTS(profile_msg(p->total)); MSG_PUTS(" "); /* make sure there is always a separating space */ msg_advance(13); msg_outnum(p->count); @@ -5733,10 +5734,10 @@ static void syntime_report(void) msg_outnum(p->match); MSG_PUTS(" "); msg_advance(26); - MSG_PUTS(profile_msg(&p->slowest)); + MSG_PUTS(profile_msg(p->slowest)); MSG_PUTS(" "); msg_advance(38); - MSG_PUTS(profile_msg(&p->average)); + MSG_PUTS(profile_msg(p->average)); MSG_PUTS(" "); msg_advance(50); msg_outtrans(HL_TABLE()[p->id - 1].sg_name); @@ -5755,7 +5756,7 @@ static void syntime_report(void) ga_clear(&ga); if (!got_int) { MSG_PUTS("\n"); - MSG_PUTS(profile_msg(&total_total)); + MSG_PUTS(profile_msg(total_total)); msg_advance(13); msg_outnum(total_count); MSG_PUTS("\n"); diff --git a/src/nvim/vim.h b/src/nvim/vim.h index 583e3384de..63b9436da7 100644 --- a/src/nvim/vim.h +++ b/src/nvim/vim.h @@ -426,8 +426,6 @@ typedef void *vim_acl_T; /* dummy to pass an ACL to a function */ * plus six following composing characters of three bytes each. */ # define MB_MAXBYTES 21 -typedef struct timeval proftime_T; - diff --git a/test/unit/profile_spec.lua b/test/unit/profile_spec.lua new file mode 100644 index 0000000000..2b006a0768 --- /dev/null +++ b/test/unit/profile_spec.lua @@ -0,0 +1,246 @@ +local helpers = require 'test.unit.helpers' + +local prof = helpers.cimport './src/nvim/profile.h' +local ffi = helpers.ffi +local eq = helpers.eq +local neq = helpers.neq + +local function split(inputstr, sep) + if sep == nil then + sep = "%s" + end + + local t, i = {}, 1 + for str in string.gmatch(inputstr, "([^"..sep.."]+)") do + t[i] = str + i = i + 1 + end + + return t +end + +local function trim(s) + local from = s:match"^%s*()" + return from > #s and "" or s:match(".*%S", from) +end + +local function starts(str, start) + return string.sub(str, 1, string.len(start)) == start +end + +local function cmp_assert(v1, v2, op, opstr) + local res = op(v1, v2) + if res == false then + print(string.format("expected: %f %s %f", v1, opstr, v2)) + end + assert.is_true(res) +end + +local function lt(v1, v2) + cmp_assert(v1, v2, function(v1, v2) return v1 < v2 end, "<") +end + +local function lte(v1, v2) + cmp_assert(v1, v2, function(v1, v2) return v1 <= v2 end, "<=") +end + +local function gt(v1, v2) + cmp_assert(v1, v2, function(v1, v2) return v1 > v2 end, ">") +end + +local function gte(v1, v2) + cmp_assert(v1, v2, function(v1, v2) return v1 >= v2 end, ">=") +end + +-- missing functions: +-- profile_self +-- profile_get_wait +-- profile_set_wait +-- profile_sub_wait +describe('profiling related functions', function() + local function profile_start() return prof.profile_start() end + local function profile_end(t) return prof.profile_end(t) end + local function profile_zero() return prof.profile_zero() end + local function profile_setlimit(ms) return prof.profile_setlimit(ms) end + local function profile_passed_limit(t) return prof.profile_passed_limit(t) end + local function profile_add(t1, t2) return prof.profile_add(t1, t2) end + local function profile_sub(t1, t2) return prof.profile_sub(t1, t2) end + local function profile_divide(t, cnt) return prof.profile_divide(t, cnt) end + local function profile_cmp(t1, t2) return prof.profile_cmp(t1, t2) end + local function profile_equal(t1, t2) return prof.profile_equal(t1, t2) end + local function profile_msg(t) return ffi.string(prof.profile_msg(t)) end + + local function toseconds(t) + local str = trim(profile_msg(t)) + local spl = split(str, ".") + local s, us = spl[1], spl[2] + return tonumber(s) + tonumber(us) / 1000000 + end + + describe('profile_equal', function() + it('times are equal to themselves', function() + local start = profile_start() + assert.is_true(profile_equal(start, start)) + + local e = profile_end(start) + assert.is_true(profile_equal(e, e)) + end) + + it('times are unequal to others', function() + assert.is_false(profile_equal(profile_start(), profile_start())) + end) + end) + + -- this is quite difficult to test, as it would rely on other functions in + -- the profiling package. Those functions in turn will probably be tested + -- using profile_cmp... circular reasoning. + describe('profile_cmp', function() + it('can compare subsequent starts', function() + local s1, s2 = profile_start(), profile_start() + assert.is_true(profile_cmp(s1, s2) > 0) + assert.is_true(profile_cmp(s2, s1) < 0) + end) + + it('can compare the zero element', function() + assert.is_true(profile_cmp(profile_zero(), profile_zero()) == 0) + end) + + it('correctly orders divisions', function() + local start = profile_start() + assert.is_true(profile_cmp(start, profile_divide(start, 10)) <= 0) + end) + end) + + describe('profile_divide', function() + it('actually performs division', function() + -- note: the routine actually performs floating-point division to get + -- better rounding behaviour, we have to take that into account when + -- checking. (check range, not exact number). + local divisor = 10 + + local start = profile_start() + local divided = profile_divide(start, divisor) + + local res = divided + for i = 1, divisor - 1 do + res = profile_add(res, divided) + end + + -- res should be in the range [start - divisor, start + divisor] + local start_min, start_max = profile_sub(start, divisor), profile_add(start, divisor) + assert.is_true(profile_cmp(start_min, res) >= 0) + assert.is_true(profile_cmp(start_max, res) <= 0) + end) + end) + + describe('profile_zero', function() + it('returns the same value on each call', function() + eq(0, profile_zero()) + assert.is_true(profile_equal(profile_zero(), profile_zero())) + end) + end) + + describe('profile_start', function() + it('increases', function() + local last = profile_start() + for i=1,100 do + local curr = profile_start() + gte(curr, last) + last = curr + end + end) + end) + + describe('profile_end', function() + it('the elapsed time cannot be zero', function() + neq(profile_zero(), profile_end(profile_start())) + end) + + it('outer elapsed >= inner elapsed', function() + for i = 1, 100 do + local start_outer = profile_start() + local start_inner = profile_start() + local elapsed_inner = profile_end(start_inner) + local elapsed_outer = profile_end(start_outer) + + gte(elapsed_outer, elapsed_inner) + end + end) + end) + + describe('profile_setlimit', function() + it('sets no limit when 0 is passed', function() + eq(true, profile_equal(profile_setlimit(0), profile_zero())) + end) + + it('sets a limit in the future otherwise', function() + local future = profile_setlimit(1000) + local now = profile_start() + assert.is_true(profile_cmp(future, now) < 0) + end) + end) + + describe('profile_passed_limit', function() + it('start is in the past', function() + local start = profile_start() + eq(true, profile_passed_limit(start)) + end) + + it('start + start is in the future', function() + local start = profile_start() + local future = profile_add(start, start) + eq(false, profile_passed_limit(future)) + end) + end) + + describe('profile_msg', function() + it('prints the zero time as 0.00000', function() + local str = trim(profile_msg(profile_zero())) + eq(str, "0.000000") + end) + + it('prints the time passed, in seconds.microsends', function() + local start = profile_start() + local endt = profile_end(start) + local str = trim(profile_msg(endt)) + local spl = split(str, ".") + + -- string has two parts (before dot and after dot) + eq(2, #spl) + + local s, us = spl[1], spl[2] + + -- zero seconds have passed (if this is not true, either LuaJIT is too + -- slow or the profiling functions are too slow and need to be fixed) + eq(s, "0") + + -- more or less the same goes for the microsecond part, if it doesn't + -- start with 0, it's too slow. + assert.is_true(starts(us, "0")) + end) + end) + + describe('profile_add', function() + it('adds profiling times', function() + local start = profile_start() + assert.equals(start, profile_add(profile_zero(), start)) + end) + end) + + describe('profile_sub', function() + it('subtracts profiling times', function() + -- subtracting zero does nothing + local start = profile_start() + assert.equals(start, profile_sub(start, profile_zero())) + + local start1, start2, start3 = profile_start(), profile_start(), profile_start() + local cmp = profile_cmp(profile_sub(start2, start1), profile_sub(start3, start1)) + -- t2 >= t1 => profile_cmp(t1, t2) >= 0 + assert.is_true(cmp >= 0) + + local cmp = profile_cmp(profile_sub(start3, start1), profile_sub(start2, start1)) + -- t2 <= t1 => profile_cmp(t1, t2) <= 0 + assert.is_true(cmp <= 0) + end) + end) +end)