From db7cd61f6297aab6343f7c6cd424d8987ca03a58 Mon Sep 17 00:00:00 2001 From: Nicolas Hillegeer Date: Sun, 15 Jun 2014 12:29:32 +0200 Subject: 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/... --- src/nvim/eval.c | 195 ++++++++++++++++++++++++++++++++++---------------------- 1 file changed, 119 insertions(+), 76 deletions(-) (limited to 'src/nvim/eval.c') 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) { + return FAIL; + } - if (arg->v_type != VAR_LIST || arg->vval.v_list == NULL - || arg->vval.v_list->lv_len != 2) + 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; - 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; + } + + // 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; } -- cgit