From 095b4479c039f9907ade4e7319cbb6a990a13438 Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Mon, 16 Jun 2014 10:16:26 +0200 Subject: [PATCH 1/5] assert: add STATIC_ASSERT macro Can be quite handy, attempt to provide fallbacks for compilers that don't support _Static_assert (which is technically a C11 feature). Suppress warnings as best we can (Clang and GCC warn that we're using a C11 feature while in C99 mode). Needs to be tested for MSVC still. --- src/nvim/assert.h | 78 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 78 insertions(+) create mode 100644 src/nvim/assert.h 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 From f172b19f438b0bccdc1be0d82a6fe660c4bbd6e0 Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Sun, 15 Jun 2014 12:28:32 +0200 Subject: [PATCH 2/5] os: implement os_hrtime Just an alias to uv_hrtime. Provides a high-resolution timer. --- src/nvim/os/time.c | 9 +++++++++ 1 file changed, 9 insertions(+) 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 From db7cd61f6297aab6343f7c6cd424d8987ca03a58 Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Sun, 15 Jun 2014 12:29:32 +0200 Subject: [PATCH 3/5] profiling: implement on top of os_hrtime() Should be better than gettimeofday() since libuv uses higher resolution clocks on most UNIX platforms. Libuv also tries to use monotonic clocks, kernel bugs notwithstanding, which is another win over gettimeofday(). Necessary for Windows, which doesn't have gettimeofday(). In vanilla vim, Windows uses QueryPerformanceCounter, which is the correct primitive for this sort of things, but that was removed when slimming up the codebase. Libuv uses QueryPerformanceCounter to implement uv_hrtime() on Windows so the behaviour of vim profiling on Windows should now be the same. The behaviour on Linux should be different (better) though, libuv uses more accurate primitives than gettimeofday(). Other misc. changes: - Added function attributes where relevant (const, pure, ...) - Convert functions to receive scalars: Now that proftime_T is always a (uint64_t) scalar (and not a struct), it's clearer to convert the functions to receive it as such instead of a pointer to a scalar. - Extract profiling funcs to profile.c: make everything clearer and reduces the size of the "catch-all" ex_cmds2.c - Add profile.{c,h} to clint and -Wconv: - Don't use sprintf, use snprintf - Don't use long, use int16_t/int32_t/... --- clint-files.txt | 2 + src/nvim/CMakeLists.txt | 2 + src/nvim/buffer_defs.h | 2 + src/nvim/eval.c | 197 +++++++++++++++++++------------ src/nvim/eval.h | 2 + src/nvim/ex_cmds2.c | 254 ++++++---------------------------------- src/nvim/ex_getln.c | 2 +- src/nvim/profile.c | 184 +++++++++++++++++++++++++++++ src/nvim/profile.h | 13 ++ src/nvim/regexp.c | 2 +- src/nvim/screen.c | 6 +- src/nvim/search.c | 2 +- src/nvim/syntax.c | 33 +++--- src/nvim/vim.h | 2 - 14 files changed, 387 insertions(+), 316 deletions(-) create mode 100644 src/nvim/profile.c create mode 100644 src/nvim/profile.h 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/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..4eb1839d40 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,184 +745,6 @@ 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; @@ -941,18 +764,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 +871,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 +892,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 +907,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 +923,7 @@ static proftime_T inchar_time; */ void prof_inchar_enter(void) { - profile_start(&inchar_time); + inchar_time = profile_start(); } /* @@ -1107,8 +931,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 +952,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 +967,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 +2434,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 +2450,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 +2773,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 +2814,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/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; - From 9386f5d41ec57f5624c27b7f8b49dd89b3d4a419 Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Thu, 3 Jul 2014 21:27:25 +0200 Subject: [PATCH 4/5] profiling: move static to function scope It wasn't used anywhere else, our coding guidelines mandate the tightest scope possible. --- src/nvim/ex_cmds2.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/nvim/ex_cmds2.c b/src/nvim/ex_cmds2.c index 4eb1839d40..c87f134ea2 100644 --- a/src/nvim/ex_cmds2.c +++ b/src/nvim/ex_cmds2.c @@ -746,13 +746,14 @@ void dbg_breakpoint(char_u *name, linenr_T lnum) } 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; From 6d0f9417ec2e9dec9666fa9c7a9b5b890f25d36a Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Tue, 15 Jul 2014 21:23:48 +0200 Subject: [PATCH 5/5] profiling: add tests Some functions are missing: - profile_self - profile_get_wait - profile_set_wait - profile_sub_wait --- test/unit/profile_spec.lua | 246 +++++++++++++++++++++++++++++++++++++ 1 file changed, 246 insertions(+) create mode 100644 test/unit/profile_spec.lua 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)