diff options
| -rwxr-xr-x | scripts/vim-patch.sh | 4 | ||||
| -rw-r--r-- | src/nvim/autocmd.c | 1 | ||||
| -rw-r--r-- | src/nvim/buffer_defs.h | 2 | ||||
| -rw-r--r-- | src/nvim/context.c | 3 | ||||
| -rw-r--r-- | src/nvim/eval.c | 260 | ||||
| -rw-r--r-- | src/nvim/eval.h | 9 | ||||
| -rw-r--r-- | src/nvim/eval/funcs.c | 1 | ||||
| -rw-r--r-- | src/nvim/eval/typval.h | 1 | ||||
| -rw-r--r-- | src/nvim/eval/userfunc.c | 9 | ||||
| -rw-r--r-- | src/nvim/eval/userfunc.h | 5 | ||||
| -rw-r--r-- | src/nvim/ex_cmds.c | 1 | ||||
| -rw-r--r-- | src/nvim/ex_cmds2.c | 399 | ||||
| -rw-r--r-- | src/nvim/ex_cmds2.h | 21 | ||||
| -rw-r--r-- | src/nvim/ex_docmd.c | 1 | ||||
| -rw-r--r-- | src/nvim/ex_getln.c | 1 | ||||
| -rw-r--r-- | src/nvim/match.c | 1 | ||||
| -rw-r--r-- | src/nvim/normal.c | 1 | ||||
| -rw-r--r-- | src/nvim/os/input.c | 1 | ||||
| -rw-r--r-- | src/nvim/os/shell.c | 1 | ||||
| -rw-r--r-- | src/nvim/profile.c | 666 | ||||
| -rw-r--r-- | src/nvim/profile.h | 3 | ||||
| -rw-r--r-- | src/nvim/regexp.c | 1 | ||||
| -rw-r--r-- | src/nvim/regexp_defs.h | 1 | ||||
| -rw-r--r-- | src/nvim/runtime.c | 3 | ||||
| -rw-r--r-- | src/nvim/runtime.h | 25 | ||||
| -rw-r--r-- | src/nvim/screen.c | 1 | ||||
| -rw-r--r-- | src/nvim/search.c | 1 | ||||
| -rw-r--r-- | src/nvim/spell.c | 1 | ||||
| -rw-r--r-- | src/nvim/syntax.c | 1 | ||||
| -rw-r--r-- | src/nvim/types.h | 2 |
30 files changed, 731 insertions, 696 deletions
diff --git a/scripts/vim-patch.sh b/scripts/vim-patch.sh index 3825d9f0ea..505a88c55c 100755 --- a/scripts/vim-patch.sh +++ b/scripts/vim-patch.sh @@ -241,6 +241,10 @@ preprocess_patch() { LC_ALL=C sed -e 's/\( [ab]\/src\/nvim\)\/map\(\.[ch]\)/\1\/mapping\2/g' \ "$file" > "$file".tmp && mv "$file".tmp "$file" + # Rename profiler.c to profile.c + LC_ALL=C sed -e 's/\( [ab]\/src\/nvim\)\/profiler\(\.[ch]\)/\1\/profile\2/g' \ + "$file" > "$file".tmp && mv "$file".tmp "$file" + # Rename session.c to ex_session.c LC_ALL=C sed -e 's/\( [ab]\/src\/nvim\)\/session\(\.[ch]\)/\1\/ex_session\2/g' \ "$file" > "$file".tmp && mv "$file".tmp "$file" diff --git a/src/nvim/autocmd.c b/src/nvim/autocmd.c index bbb044fba3..1186eea62c 100644 --- a/src/nvim/autocmd.c +++ b/src/nvim/autocmd.c @@ -24,6 +24,7 @@ #include "nvim/map.h" #include "nvim/option.h" #include "nvim/os/input.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/search.h" #include "nvim/state.h" diff --git a/src/nvim/buffer_defs.h b/src/nvim/buffer_defs.h index 3ef5ea7e02..38f701ea7d 100644 --- a/src/nvim/buffer_defs.h +++ b/src/nvim/buffer_defs.h @@ -36,8 +36,6 @@ typedef struct { #include "nvim/hashtab.h" // for dict_T #include "nvim/eval/typval.h" -// for proftime_T -#include "nvim/profile.h" // for String #include "nvim/api/private/defs.h" // for Map(K, V) diff --git a/src/nvim/context.c b/src/nvim/context.c index db26667009..e3ae9355bf 100644 --- a/src/nvim/context.c +++ b/src/nvim/context.c @@ -9,6 +9,7 @@ #include "nvim/api/vimscript.h" #include "nvim/context.h" #include "nvim/eval/encode.h" +#include "nvim/eval/userfunc.h" #include "nvim/ex_docmd.h" #include "nvim/option.h" #include "nvim/shada.h" @@ -249,7 +250,7 @@ static inline void ctx_save_funcs(Context *ctx, bool scriptonly) ctx->funcs = (Array)ARRAY_DICT_INIT; Error err = ERROR_INIT; - HASHTAB_ITER(&func_hashtab, hi, { + HASHTAB_ITER(func_tbl_get(), hi, { const char_u *const name = hi->hi_key; bool islambda = (STRNCMP(name, "<lambda>", 8) == 0); bool isscript = (name[0] == K_SPECIAL); diff --git a/src/nvim/eval.c b/src/nvim/eval.c index 5abaf88e60..42a3c7df80 100644 --- a/src/nvim/eval.c +++ b/src/nvim/eval.c @@ -44,6 +44,7 @@ #include "nvim/os/input.h" #include "nvim/os/shell.h" #include "nvim/path.h" +#include "nvim/profile.h" #include "nvim/quickfix.h" #include "nvim/regexp.h" #include "nvim/screen.h" @@ -1192,42 +1193,6 @@ void *call_func_retlist(const char *func, int argc, typval_T *argv) return rettv.vval.v_list; } -/// Prepare profiling for entering a child or something else that is not -/// counted for the script/function itself. -/// Should always be called in pair with prof_child_exit(). -/// -/// @param tm place to store waittime -void prof_child_enter(proftime_T *tm) -{ - funccall_T *fc = get_current_funccal(); - - if (fc != NULL && fc->func->uf_profiling) { - fc->prof_child = profile_start(); - } - - script_prof_save(tm); -} - -/// Take care of time spent in a child. -/// Should always be called after prof_child_enter(). -/// -/// @param tm where waittime was stored -void prof_child_exit(proftime_T *tm) -{ - funccall_T *fc = get_current_funccal(); - - if (fc != NULL && fc->func->uf_profiling) { - 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); -} - /// Evaluate 'foldexpr'. Returns the foldlevel, and any character preceding /// it in "*cp". Doesn't give error messages. int eval_foldexpr(char *arg, int *cp) @@ -7941,174 +7906,6 @@ const char *find_option_end(const char **const arg, int *const opt_flags) return p; } -/// Start profiling function "fp". -void func_do_profile(ufunc_T *fp) -{ - int len = fp->uf_lines.ga_len; - - if (!fp->uf_prof_initialized) { - if (len == 0) { - len = 1; // avoid getting error for allocating zero bytes - } - fp->uf_tm_count = 0; - fp->uf_tm_self = profile_zero(); - fp->uf_tm_total = profile_zero(); - - if (fp->uf_tml_count == NULL) { - fp->uf_tml_count = xcalloc((size_t)len, sizeof(int)); - } - - if (fp->uf_tml_total == NULL) { - fp->uf_tml_total = xcalloc((size_t)len, sizeof(proftime_T)); - } - - if (fp->uf_tml_self == NULL) { - fp->uf_tml_self = xcalloc((size_t)len, sizeof(proftime_T)); - } - - fp->uf_tml_idx = -1; - fp->uf_prof_initialized = true; - } - - fp->uf_profiling = TRUE; -} - -/// Dump the profiling results for all functions in file "fd". -void func_dump_profile(FILE *fd) -{ - hashitem_T *hi; - int todo; - ufunc_T *fp; - ufunc_T **sorttab; - int st_len = 0; - - todo = (int)func_hashtab.ht_used; - if (todo == 0) { - return; // nothing to dump - } - - sorttab = xmalloc(sizeof(ufunc_T *) * (size_t)todo); - - for (hi = func_hashtab.ht_array; todo > 0; ++hi) { - if (!HASHITEM_EMPTY(hi)) { - --todo; - fp = HI2UF(hi); - if (fp->uf_prof_initialized) { - sorttab[st_len++] = fp; - - if (fp->uf_name[0] == K_SPECIAL) { - fprintf(fd, "FUNCTION <SNR>%s()\n", fp->uf_name + 3); - } else { - fprintf(fd, "FUNCTION %s()\n", fp->uf_name); - } - if (fp->uf_script_ctx.sc_sid != 0) { - bool should_free; - const LastSet last_set = (LastSet){ - .script_ctx = fp->uf_script_ctx, - .channel_id = 0, - }; - char *p = (char *)get_scriptname(last_set, &should_free); - fprintf(fd, " Defined: %s:%" PRIdLINENR "\n", - p, fp->uf_script_ctx.sc_lnum); - if (should_free) { - xfree(p); - } - } - if (fp->uf_tm_count == 1) { - 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, "\n"); - fprintf(fd, "count total (s) self (s)\n"); - - for (int i = 0; i < fp->uf_lines.ga_len; ++i) { - if (FUNCLINE(fp, i) == NULL) { - continue; - } - prof_func_line(fd, fp->uf_tml_count[i], - &fp->uf_tml_total[i], &fp->uf_tml_self[i], TRUE); - fprintf(fd, "%s\n", FUNCLINE(fp, i)); - } - fprintf(fd, "\n"); - } - } - } - - if (st_len > 0) { - qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), - prof_total_cmp); - prof_sort_list(fd, sorttab, st_len, "TOTAL", FALSE); - qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), - prof_self_cmp); - prof_sort_list(fd, sorttab, st_len, "SELF", TRUE); - } - - xfree(sorttab); -} - -/// @param prefer_self when equal print only self time -static void prof_sort_list(FILE *fd, ufunc_T **sorttab, int st_len, char *title, int prefer_self) -{ - int i; - ufunc_T *fp; - - fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title); - fprintf(fd, "count total (s) self (s) function\n"); - for (i = 0; i < 20 && i < st_len; ++i) { - fp = sorttab[i]; - prof_func_line(fd, fp->uf_tm_count, &fp->uf_tm_total, &fp->uf_tm_self, - prefer_self); - if (fp->uf_name[0] == K_SPECIAL) { - fprintf(fd, " <SNR>%s()\n", fp->uf_name + 3); - } else { - fprintf(fd, " %s()\n", fp->uf_name); - } - } - fprintf(fd, "\n"); -} - -/// Print the count and times for one function or function line. -/// -/// @param prefer_self when equal print only self time -static void prof_func_line(FILE *fd, int count, proftime_T *total, proftime_T *self, - int prefer_self) -{ - if (count > 0) { - fprintf(fd, "%5d ", count); - 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, " "); - } else { - fprintf(fd, "%s ", profile_msg(*self)); - } - } else { - fprintf(fd, " "); - } -} - -/// Compare function for total time sorting. -static int prof_total_cmp(const void *s1, const void *s2) -{ - ufunc_T *p1 = *(ufunc_T **)s1; - ufunc_T *p2 = *(ufunc_T **)s2; - return profile_cmp(p1->uf_tm_total, p2->uf_tm_total); -} - -/// Compare function for self time sorting. -static int prof_self_cmp(const void *s1, const void *s2) -{ - ufunc_T *p1 = *(ufunc_T **)s1; - ufunc_T *p2 = *(ufunc_T **)s2; - return profile_cmp(p1->uf_tm_self, p2->uf_tm_self); -} - /// Return the autoload script name for a function or variable name /// Caller must make sure that "name" contains AUTOLOAD_CHAR. /// @@ -8183,61 +7980,6 @@ bool script_autoload(const char *const name, const size_t name_len, const bool r return ret; } -/// Called when starting to read a function line. -/// "sourcing_lnum" must be correct! -/// When skipping lines it may not actually be executed, but we won't find out -/// until later and we need to store the time now. -void func_line_start(void *cookie) -{ - funccall_T *fcp = (funccall_T *)cookie; - ufunc_T *fp = fcp->func; - - if (fp->uf_profiling && sourcing_lnum >= 1 - && sourcing_lnum <= fp->uf_lines.ga_len) { - fp->uf_tml_idx = sourcing_lnum - 1; - // Skip continuation lines. - while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL) { - fp->uf_tml_idx--; - } - fp->uf_tml_execed = false; - fp->uf_tml_start = profile_start(); - fp->uf_tml_children = profile_zero(); - fp->uf_tml_wait = profile_get_wait(); - } -} - -/// Called when actually executing a function line. -void func_line_exec(void *cookie) -{ - funccall_T *fcp = (funccall_T *)cookie; - ufunc_T *fp = fcp->func; - - if (fp->uf_profiling && fp->uf_tml_idx >= 0) { - fp->uf_tml_execed = TRUE; - } -} - -/// Called when done with a function line. -void func_line_end(void *cookie) -{ - funccall_T *fcp = (funccall_T *)cookie; - ufunc_T *fp = fcp->func; - - if (fp->uf_profiling && fp->uf_tml_idx >= 0) { - if (fp->uf_tml_execed) { - ++fp->uf_tml_count[fp->uf_tml_idx]; - 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; - } -} - static var_flavour_T var_flavour(char *varname) FUNC_ATTR_PURE { diff --git a/src/nvim/eval.h b/src/nvim/eval.h index 7dbd18737a..b0cb5fd8c1 100644 --- a/src/nvim/eval.h +++ b/src/nvim/eval.h @@ -11,15 +11,6 @@ #define COPYID_INC 2 #define COPYID_MASK (~0x1) -// All user-defined functions are found in this hashtable. -extern hashtab_T func_hashtab; - -// From user function to hashitem and back. -EXTERN ufunc_T dumuf; -#define UF2HIKEY(fp) ((fp)->uf_name) -#define HIKEY2UF(p) ((ufunc_T *)(p - offsetof(ufunc_T, uf_name))) -#define HI2UF(hi) HIKEY2UF((hi)->hi_key) - /* * Structure returned by get_lval() and used by set_var_lval(). * For a plain name: diff --git a/src/nvim/eval/funcs.c b/src/nvim/eval/funcs.c index 4a44c08457..5c21825897 100644 --- a/src/nvim/eval/funcs.c +++ b/src/nvim/eval/funcs.c @@ -58,6 +58,7 @@ #include "nvim/path.h" #include "nvim/plines.h" #include "nvim/popupmnu.h" +#include "nvim/profile.h" #include "nvim/quickfix.h" #include "nvim/regexp.h" #include "nvim/screen.h" diff --git a/src/nvim/eval/typval.h b/src/nvim/eval/typval.h index 2a4dd7b146..e411419a07 100644 --- a/src/nvim/eval/typval.h +++ b/src/nvim/eval/typval.h @@ -16,7 +16,6 @@ #include "nvim/mbyte_defs.h" #include "nvim/message.h" #include "nvim/pos.h" // for linenr_T -#include "nvim/profile.h" // for proftime_T #include "nvim/types.h" #ifdef LOG_LIST_ACTIONS # include "nvim/memory.h" diff --git a/src/nvim/eval/userfunc.c b/src/nvim/eval/userfunc.c index 38a00099bc..72a8c45326 100644 --- a/src/nvim/eval/userfunc.c +++ b/src/nvim/eval/userfunc.c @@ -21,6 +21,7 @@ #include "nvim/insexpand.h" #include "nvim/lua/executor.h" #include "nvim/os/input.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/search.h" #include "nvim/ui.h" @@ -44,7 +45,7 @@ # include "eval/userfunc.c.generated.h" #endif -hashtab_T func_hashtab; +static hashtab_T func_hashtab; // Used by get_func_tv() static garray_T funcargs = GA_EMPTY_INIT_VALUE; @@ -66,6 +67,12 @@ void func_init(void) hash_init(&func_hashtab); } +/// Return the function hash table +hashtab_T *func_tbl_get(void) +{ + return &func_hashtab; +} + /// Get function arguments. static int get_function_args(char_u **argp, char_u endchar, garray_T *newargs, int *varargs, garray_T *default_args, bool skip) diff --git a/src/nvim/eval/userfunc.h b/src/nvim/eval/userfunc.h index ed86aaad4a..7edf69d13b 100644 --- a/src/nvim/eval/userfunc.h +++ b/src/nvim/eval/userfunc.h @@ -4,6 +4,11 @@ #include "nvim/eval/typval.h" #include "nvim/ex_cmds_defs.h" +// From user function to hashitem and back. +#define UF2HIKEY(fp) ((fp)->uf_name) +#define HIKEY2UF(p) ((ufunc_T *)(p - offsetof(ufunc_T, uf_name))) +#define HI2UF(hi) HIKEY2UF((hi)->hi_key) + ///< Structure used by trans_function_name() typedef struct { dict_T *fd_dict; ///< Dictionary used. diff --git a/src/nvim/ex_cmds.c b/src/nvim/ex_cmds.c index 9ad65500e9..8f22fe6178 100644 --- a/src/nvim/ex_cmds.c +++ b/src/nvim/ex_cmds.c @@ -60,6 +60,7 @@ #include "nvim/os_unix.h" #include "nvim/path.h" #include "nvim/plines.h" +#include "nvim/profile.h" #include "nvim/quickfix.h" #include "nvim/regexp.h" #include "nvim/screen.h" diff --git a/src/nvim/ex_cmds2.c b/src/nvim/ex_cmds2.c index 730a2f1b69..382780adec 100644 --- a/src/nvim/ex_cmds2.c +++ b/src/nvim/ex_cmds2.c @@ -54,17 +54,6 @@ #include "nvim/version.h" #include "nvim/window.h" -/// Growarray to store info about already sourced scripts. -static garray_T script_items = { 0, 0, sizeof(scriptitem_T), 4, NULL }; -#define SCRIPT_ITEM(id) (((scriptitem_T *)script_items.ga_data)[(id) - 1]) - -// Struct used in sn_prl_ga for every line of a script. -typedef struct sn_prl_S { - int snp_count; ///< nr of times line was executed - proftime_T sn_prl_total; ///< time spent in a line + children - proftime_T sn_prl_self; ///< time spent in a line itself -} sn_prl_T; - /// Structure used to store info for each sourced file. /// It is shared between do_source() and getsourceline(). /// This is required, because it needs to be handed to do_cmdline() and @@ -85,58 +74,10 @@ struct source_cookie { vimconv_T conv; ///< type of conversion }; -#define PRL_ITEM(si, idx) (((sn_prl_T *)(si)->sn_prl_ga.ga_data)[(idx)]) - #ifdef INCLUDE_GENERATED_DECLARATIONS # include "ex_cmds2.c.generated.h" #endif -static char *profile_fname = NULL; - -/// ":profile cmd args" -void ex_profile(exarg_T *eap) -{ - static proftime_T pause_time; - - char *e; - int len; - - e = (char *)skiptowhite((char_u *)eap->arg); - len = (int)(e - eap->arg); - e = skipwhite(e); - - if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) { - xfree(profile_fname); - profile_fname = (char *)expand_env_save_opt((char_u *)e, true); - do_profiling = PROF_YES; - 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, "stop") == 0) { - profile_dump(); - do_profiling = PROF_NONE; - set_vim_var_nr(VV_PROFILING, 0L); - profile_reset(); - } else if (STRCMP(eap->arg, "pause") == 0) { - if (do_profiling == PROF_YES) { - pause_time = profile_start(); - } - do_profiling = PROF_PAUSED; - } else if (STRCMP(eap->arg, "continue") == 0) { - if (do_profiling == PROF_PAUSED) { - pause_time = profile_end(pause_time); - profile_set_wait(profile_add(profile_get_wait(), pause_time)); - } - do_profiling = PROF_YES; - } else if (STRCMP(eap->arg, "dump") == 0) { - profile_dump(); - } else { - // The rest is similar to ":breakadd". - ex_breakadd(eap); - } -} - void ex_ruby(exarg_T *eap) { script_host_execute("ruby", eap); @@ -182,273 +123,6 @@ void ex_perldo(exarg_T *eap) script_host_do_range("perl", eap); } -// Command line expansion for :profile. -static enum { - PEXP_SUBCMD, ///< expand :profile sub-commands - PEXP_FUNC, ///< expand :profile func {funcname} -} pexpand_what; - -static char *pexpand_cmds[] = { - "continue", - "dump", - "file", - "func", - "pause", - "start", - "stop", - NULL -}; - -/// Function given to ExpandGeneric() to obtain the profile command -/// specific expansion. -char *get_profile_name(expand_T *xp, int idx) - FUNC_ATTR_PURE -{ - switch (pexpand_what) { - case PEXP_SUBCMD: - return pexpand_cmds[idx]; - // case PEXP_FUNC: TODO - default: - return NULL; - } -} - -/// Handle command line completion for :profile command. -void set_context_in_profile_cmd(expand_T *xp, const char *arg) -{ - // Default: expand subcommands. - xp->xp_context = EXPAND_PROFILE; - pexpand_what = PEXP_SUBCMD; - xp->xp_pattern = (char *)arg; - - char_u *const end_subcmd = skiptowhite((const char_u *)arg); - if (*end_subcmd == NUL) { - return; - } - - if ((const char *)end_subcmd - arg == 5 && strncmp(arg, "start", 5) == 0) { - xp->xp_context = EXPAND_FILES; - xp->xp_pattern = skipwhite((char *)end_subcmd); - return; - } - - // TODO(tarruda): expand function names after "func" - xp->xp_context = EXPAND_NOTHING; -} - -/// Dump the profiling info. -void profile_dump(void) -{ - FILE *fd; - - if (profile_fname != NULL) { - fd = os_fopen(profile_fname, "w"); - if (fd == NULL) { - semsg(_(e_notopen), profile_fname); - } else { - script_dump_profile(fd); - func_dump_profile(fd); - fclose(fd); - } - } -} - -/// Reset all profiling information. -static void profile_reset(void) -{ - // Reset sourced files. - for (int id = 1; id <= script_items.ga_len; id++) { - scriptitem_T *si = &SCRIPT_ITEM(id); - if (si->sn_prof_on) { - si->sn_prof_on = false; - si->sn_pr_force = false; - si->sn_pr_child = profile_zero(); - si->sn_pr_nest = 0; - si->sn_pr_count = 0; - si->sn_pr_total = profile_zero(); - si->sn_pr_self = profile_zero(); - si->sn_pr_start = profile_zero(); - si->sn_pr_children = profile_zero(); - ga_clear(&si->sn_prl_ga); - si->sn_prl_start = profile_zero(); - si->sn_prl_children = profile_zero(); - si->sn_prl_wait = profile_zero(); - si->sn_prl_idx = -1; - si->sn_prl_execed = 0; - } - } - - // Reset functions. - size_t n = func_hashtab.ht_used; - hashitem_T *hi = func_hashtab.ht_array; - - for (; n > (size_t)0; hi++) { - if (!HASHITEM_EMPTY(hi)) { - n--; - ufunc_T *uf = HI2UF(hi); - if (uf->uf_prof_initialized) { - uf->uf_profiling = 0; - uf->uf_tm_count = 0; - uf->uf_tm_total = profile_zero(); - uf->uf_tm_self = profile_zero(); - uf->uf_tm_children = profile_zero(); - - for (int i = 0; i < uf->uf_lines.ga_len; i++) { - uf->uf_tml_count[i] = 0; - uf->uf_tml_total[i] = uf->uf_tml_self[i] = 0; - } - - uf->uf_tml_start = profile_zero(); - uf->uf_tml_children = profile_zero(); - uf->uf_tml_wait = profile_zero(); - uf->uf_tml_idx = -1; - uf->uf_tml_execed = 0; - } - } - } - - XFREE_CLEAR(profile_fname); -} - -/// Start profiling a script. -static void profile_init(scriptitem_T *si) -{ - si->sn_pr_count = 0; - 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; - si->sn_prof_on = true; - si->sn_pr_nest = 0; -} - -/// Save time when starting to invoke another script or function. -/// -/// @param tm place to store wait time -void script_prof_save(proftime_T *tm) -{ - scriptitem_T *si; - - if (current_sctx.sc_sid > 0 && current_sctx.sc_sid <= script_items.ga_len) { - si = &SCRIPT_ITEM(current_sctx.sc_sid); - if (si->sn_prof_on && si->sn_pr_nest++ == 0) { - si->sn_pr_child = profile_start(); - } - } - *tm = profile_get_wait(); -} - -/// Count time spent in children after invoking another script or function. -void script_prof_restore(proftime_T *tm) -{ - scriptitem_T *si; - - if (current_sctx.sc_sid > 0 && current_sctx.sc_sid <= script_items.ga_len) { - si = &SCRIPT_ITEM(current_sctx.sc_sid); - if (si->sn_prof_on && --si->sn_pr_nest == 0) { - 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); - } - } -} - -static proftime_T inchar_time; - -/// Called when starting to wait for the user to type a character. -void prof_inchar_enter(void) -{ - inchar_time = profile_start(); -} - -/// Called when finished waiting for the user to type a character. -void prof_inchar_exit(void) -{ - inchar_time = profile_end(inchar_time); - profile_set_wait(profile_add(profile_get_wait(), inchar_time)); -} - -/// Dump the profiling results for all scripts in file "fd". -static void script_dump_profile(FILE *fd) -{ - scriptitem_T *si; - FILE *sfd; - sn_prl_T *pp; - - for (int id = 1; id <= script_items.ga_len; id++) { - si = &SCRIPT_ITEM(id); - if (si->sn_prof_on) { - fprintf(fd, "SCRIPT %s\n", si->sn_name); - if (si->sn_pr_count == 1) { - 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, "\n"); - fprintf(fd, "count total (s) self (s)\n"); - - sfd = os_fopen((char *)si->sn_name, "r"); - if (sfd == NULL) { - fprintf(fd, "Cannot open file!\n"); - } else { - // Keep going till the end of file, so that trailing - // continuation lines are listed. - for (int i = 0;; i++) { - if (vim_fgets(IObuff, IOSIZE, sfd)) { - break; - } - // When a line has been truncated, append NL, taking care - // of multi-byte characters . - if (IObuff[IOSIZE - 2] != NUL && IObuff[IOSIZE - 2] != NL) { - int n = IOSIZE - 2; - - // Move to the first byte of this char. - // utf_head_off() doesn't work, because it checks - // for a truncated character. - while (n > 0 && (IObuff[n] & 0xc0) == 0x80) { - n--; - } - - IObuff[n] = NL; - IObuff[n + 1] = NUL; - } - if (i < si->sn_prl_ga.ga_len - && (pp = &PRL_ITEM(si, i))->snp_count > 0) { - fprintf(fd, "%5d ", pp->snp_count); - 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)); - } else { - fprintf(fd, " "); - } - fprintf(fd, "%s", IObuff); - } - fclose(sfd); - } - fprintf(fd, "\n"); - } - } -} - -/// @return true when a function defined in the current script should be -/// profiled. -bool prof_def_func(void) - FUNC_ATTR_PURE -{ - if (current_sctx.sc_sid > 0) { - return SCRIPT_ITEM(current_sctx.sc_sid).sn_pr_force; - } - return false; -} - /// If 'autowrite' option set, try to write the file. /// Careful: autocommands may make "buf" invalid! /// @@ -2468,79 +2142,6 @@ retry: return NULL; } -/// Called when starting to read a script line. -/// "sourcing_lnum" must be correct! -/// When skipping lines it may not actually be executed, but we won't find out -/// until later and we need to store the time now. -void script_line_start(void) -{ - scriptitem_T *si; - sn_prl_T *pp; - - if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) { - return; - } - si = &SCRIPT_ITEM(current_sctx.sc_sid); - if (si->sn_prof_on && sourcing_lnum >= 1) { - // Grow the array before starting the timer, so that the time spent - // here isn't counted. - (void)ga_grow(&si->sn_prl_ga, sourcing_lnum - si->sn_prl_ga.ga_len); - si->sn_prl_idx = sourcing_lnum - 1; - while (si->sn_prl_ga.ga_len <= si->sn_prl_idx - && si->sn_prl_ga.ga_len < si->sn_prl_ga.ga_maxlen) { - // Zero counters for a line that was not used before. - pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len); - pp->snp_count = 0; - pp->sn_prl_total = profile_zero(); - pp->sn_prl_self = profile_zero(); - si->sn_prl_ga.ga_len++; - } - si->sn_prl_execed = false; - si->sn_prl_start = profile_start(); - si->sn_prl_children = profile_zero(); - si->sn_prl_wait = profile_get_wait(); - } -} - -/// Called when actually executing a function line. -void script_line_exec(void) -{ - scriptitem_T *si; - - if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) { - return; - } - si = &SCRIPT_ITEM(current_sctx.sc_sid); - if (si->sn_prof_on && si->sn_prl_idx >= 0) { - si->sn_prl_execed = true; - } -} - -/// Called when done with a function line. -void script_line_end(void) -{ - scriptitem_T *si; - sn_prl_T *pp; - - if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) { - return; - } - si = &SCRIPT_ITEM(current_sctx.sc_sid); - if (si->sn_prof_on && si->sn_prl_idx >= 0 - && si->sn_prl_idx < si->sn_prl_ga.ga_len) { - if (si->sn_prl_execed) { - pp = &PRL_ITEM(si, si->sn_prl_idx); - pp->snp_count++; - 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; - } -} - /// ":scriptencoding": Set encoding conversion for a sourced script. /// Without the multi-byte feature it's simply ignored. void ex_scriptencoding(exarg_T *eap) diff --git a/src/nvim/ex_cmds2.h b/src/nvim/ex_cmds2.h index c463bfa5ab..95433fde90 100644 --- a/src/nvim/ex_cmds2.h +++ b/src/nvim/ex_cmds2.h @@ -15,27 +15,6 @@ #define CCGD_ALLBUF 8 // may write all buffers #define CCGD_EXCMD 16 // may suggest using ! -typedef struct scriptitem_S { - char_u *sn_name; - bool sn_prof_on; ///< true when script is/was profiled - bool sn_pr_force; ///< forceit: profile functions in this script - proftime_T sn_pr_child; ///< time set when going into first child - int sn_pr_nest; ///< nesting for sn_pr_child - // profiling the script as a whole - int sn_pr_count; ///< nr of times sourced - proftime_T sn_pr_total; ///< time spent in script + children - proftime_T sn_pr_self; ///< time spent in script itself - proftime_T sn_pr_start; ///< time at script start - proftime_T sn_pr_children; ///< time in children after script start - // profiling the script per line - garray_T sn_prl_ga; ///< things stored for every line - proftime_T sn_prl_start; ///< start time for current line - proftime_T sn_prl_children; ///< time spent in children for this line - proftime_T sn_prl_wait; ///< wait start time for current line - linenr_T sn_prl_idx; ///< index of line being timed; -1 if none - int sn_prl_execed; ///< line being timed was executed -} scriptitem_T; - #ifdef INCLUDE_GENERATED_DECLARATIONS # include "ex_cmds2.h.generated.h" #endif diff --git a/src/nvim/ex_docmd.c b/src/nvim/ex_docmd.c index e8dc0b8e86..e482c9e9cf 100644 --- a/src/nvim/ex_docmd.c +++ b/src/nvim/ex_docmd.c @@ -64,6 +64,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" diff --git a/src/nvim/ex_getln.c b/src/nvim/ex_getln.c index 22bbefe827..bba8aa5343 100644 --- a/src/nvim/ex_getln.c +++ b/src/nvim/ex_getln.c @@ -65,6 +65,7 @@ #include "nvim/os_unix.h" #include "nvim/path.h" #include "nvim/popupmnu.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/screen.h" #include "nvim/search.h" diff --git a/src/nvim/match.c b/src/nvim/match.c index ba587c4141..291f7ab696 100644 --- a/src/nvim/match.c +++ b/src/nvim/match.c @@ -12,6 +12,7 @@ #include "nvim/highlight_group.h" #include "nvim/match.h" #include "nvim/memline.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/runtime.h" #include "nvim/screen.h" diff --git a/src/nvim/normal.c b/src/nvim/normal.c index 1657b391d0..5ff35d4922 100644 --- a/src/nvim/normal.c +++ b/src/nvim/normal.c @@ -51,6 +51,7 @@ #include "nvim/os/input.h" #include "nvim/os/time.h" #include "nvim/plines.h" +#include "nvim/profile.h" #include "nvim/quickfix.h" #include "nvim/screen.h" #include "nvim/search.h" diff --git a/src/nvim/os/input.c b/src/nvim/os/input.c index c47a891c18..da3f68edc7 100644 --- a/src/nvim/os/input.c +++ b/src/nvim/os/input.c @@ -19,6 +19,7 @@ #include "nvim/memory.h" #include "nvim/msgpack_rpc/channel.h" #include "nvim/os/input.h" +#include "nvim/profile.h" #include "nvim/screen.h" #include "nvim/state.h" #include "nvim/ui.h" diff --git a/src/nvim/os/shell.c b/src/nvim/os/shell.c index 8f2018c1f4..dd44cb1ce7 100644 --- a/src/nvim/os/shell.c +++ b/src/nvim/os/shell.c @@ -25,6 +25,7 @@ #include "nvim/os/shell.h" #include "nvim/os/signal.h" #include "nvim/path.h" +#include "nvim/profile.h" #include "nvim/screen.h" #include "nvim/strings.h" #include "nvim/tag.h" diff --git a/src/nvim/profile.c b/src/nvim/profile.c index fe7bd2e912..a77680c9f2 100644 --- a/src/nvim/profile.c +++ b/src/nvim/profile.c @@ -6,16 +6,33 @@ #include <stdio.h> #include "nvim/assert.h" +#include "nvim/charset.h" +#include "nvim/debugger.h" +#include "nvim/eval.h" +#include "nvim/eval/userfunc.h" +#include "nvim/ex_cmds2.h" +#include "nvim/fileio.h" #include "nvim/func_attr.h" #include "nvim/globals.h" // for the global `time_fd` (startuptime) -#include "nvim/os/os_defs.h" +#include "nvim/os/os.h" #include "nvim/os/time.h" #include "nvim/profile.h" +#include "nvim/runtime.h" +#include "nvim/vim.h" #ifdef INCLUDE_GENERATED_DECLARATIONS # include "profile.c.generated.h" #endif +/// Struct used in sn_prl_ga for every line of a script. +typedef struct sn_prl_S { + int snp_count; ///< nr of times line was executed + proftime_T sn_prl_total; ///< time spent in a line + children + proftime_T sn_prl_self; ///< time spent in a line itself +} sn_prl_T; + +#define PRL_ITEM(si, idx) (((sn_prl_T *)(si)->sn_prl_ga.ga_data)[(idx)]) + static proftime_T prof_wait_time; /// Gets the current time. @@ -195,6 +212,653 @@ int profile_cmp(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST return profile_signed(tm2 - tm1) < 0 ? -1 : 1; } +static char *profile_fname = NULL; + +/// Reset all profiling information. +void profile_reset(void) +{ + // Reset sourced files. + for (int id = 1; id <= script_items.ga_len; id++) { + scriptitem_T *si = &SCRIPT_ITEM(id); + if (si->sn_prof_on) { + si->sn_prof_on = false; + si->sn_pr_force = false; + si->sn_pr_child = profile_zero(); + si->sn_pr_nest = 0; + si->sn_pr_count = 0; + si->sn_pr_total = profile_zero(); + si->sn_pr_self = profile_zero(); + si->sn_pr_start = profile_zero(); + si->sn_pr_children = profile_zero(); + ga_clear(&si->sn_prl_ga); + si->sn_prl_start = profile_zero(); + si->sn_prl_children = profile_zero(); + si->sn_prl_wait = profile_zero(); + si->sn_prl_idx = -1; + si->sn_prl_execed = 0; + } + } + + // Reset functions. + hashtab_T *const functbl = func_tbl_get(); + size_t todo = functbl->ht_used; + hashitem_T *hi = functbl->ht_array; + + for (; todo > (size_t)0; hi++) { + if (!HASHITEM_EMPTY(hi)) { + todo--; + ufunc_T *uf = HI2UF(hi); + if (uf->uf_prof_initialized) { + uf->uf_profiling = 0; + uf->uf_tm_count = 0; + uf->uf_tm_total = profile_zero(); + uf->uf_tm_self = profile_zero(); + uf->uf_tm_children = profile_zero(); + + for (int i = 0; i < uf->uf_lines.ga_len; i++) { + uf->uf_tml_count[i] = 0; + uf->uf_tml_total[i] = uf->uf_tml_self[i] = 0; + } + + uf->uf_tml_start = profile_zero(); + uf->uf_tml_children = profile_zero(); + uf->uf_tml_wait = profile_zero(); + uf->uf_tml_idx = -1; + uf->uf_tml_execed = 0; + } + } + } + + XFREE_CLEAR(profile_fname); +} + +/// ":profile cmd args" +void ex_profile(exarg_T *eap) +{ + static proftime_T pause_time; + + char *e; + int len; + + e = (char *)skiptowhite((char_u *)eap->arg); + len = (int)(e - eap->arg); + e = skipwhite(e); + + if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) { + xfree(profile_fname); + profile_fname = (char *)expand_env_save_opt((char_u *)e, true); + do_profiling = PROF_YES; + 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, "stop") == 0) { + profile_dump(); + do_profiling = PROF_NONE; + set_vim_var_nr(VV_PROFILING, 0L); + profile_reset(); + } else if (STRCMP(eap->arg, "pause") == 0) { + if (do_profiling == PROF_YES) { + pause_time = profile_start(); + } + do_profiling = PROF_PAUSED; + } else if (STRCMP(eap->arg, "continue") == 0) { + if (do_profiling == PROF_PAUSED) { + pause_time = profile_end(pause_time); + profile_set_wait(profile_add(profile_get_wait(), pause_time)); + } + do_profiling = PROF_YES; + } else if (STRCMP(eap->arg, "dump") == 0) { + profile_dump(); + } else { + // The rest is similar to ":breakadd". + ex_breakadd(eap); + } +} + +/// Command line expansion for :profile. +static enum { + PEXP_SUBCMD, ///< expand :profile sub-commands + PEXP_FUNC, ///< expand :profile func {funcname} +} pexpand_what; + +static char *pexpand_cmds[] = { + "continue", + "dump", + "file", + "func", + "pause", + "start", + "stop", + NULL +}; + +/// Function given to ExpandGeneric() to obtain the profile command +/// specific expansion. +char *get_profile_name(expand_T *xp, int idx) + FUNC_ATTR_PURE +{ + switch (pexpand_what) { + case PEXP_SUBCMD: + return pexpand_cmds[idx]; + // case PEXP_FUNC: TODO + default: + return NULL; + } +} + +/// Handle command line completion for :profile command. +void set_context_in_profile_cmd(expand_T *xp, const char *arg) +{ + // Default: expand subcommands. + xp->xp_context = EXPAND_PROFILE; + pexpand_what = PEXP_SUBCMD; + xp->xp_pattern = (char *)arg; + + char_u *const end_subcmd = skiptowhite((const char_u *)arg); + if (*end_subcmd == NUL) { + return; + } + + if ((const char *)end_subcmd - arg == 5 && strncmp(arg, "start", 5) == 0) { + xp->xp_context = EXPAND_FILES; + xp->xp_pattern = skipwhite((char *)end_subcmd); + return; + } + + // TODO(tarruda): expand function names after "func" + xp->xp_context = EXPAND_NOTHING; +} + +static proftime_T inchar_time; + +/// Called when starting to wait for the user to type a character. +void prof_inchar_enter(void) +{ + inchar_time = profile_start(); +} + +/// Called when finished waiting for the user to type a character. +void prof_inchar_exit(void) +{ + inchar_time = profile_end(inchar_time); + profile_set_wait(profile_add(profile_get_wait(), inchar_time)); +} + +/// @return true when a function defined in the current script should be +/// profiled. +bool prof_def_func(void) + FUNC_ATTR_PURE +{ + if (current_sctx.sc_sid > 0) { + return SCRIPT_ITEM(current_sctx.sc_sid).sn_pr_force; + } + return false; +} + +/// Print the count and times for one function or function line. +/// +/// @param prefer_self when equal print only self time +static void prof_func_line(FILE *fd, int count, proftime_T *total, proftime_T *self, + bool prefer_self) +{ + if (count > 0) { + fprintf(fd, "%5d ", count); + 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, " "); + } else { + fprintf(fd, "%s ", profile_msg(*self)); + } + } else { + fprintf(fd, " "); + } +} + +/// @param prefer_self when equal print only self time +static void prof_sort_list(FILE *fd, ufunc_T **sorttab, int st_len, char *title, bool prefer_self) +{ + int i; + ufunc_T *fp; + + fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title); + fprintf(fd, "count total (s) self (s) function\n"); + for (i = 0; i < 20 && i < st_len; i++) { + fp = sorttab[i]; + prof_func_line(fd, fp->uf_tm_count, &fp->uf_tm_total, &fp->uf_tm_self, + prefer_self); + if (fp->uf_name[0] == K_SPECIAL) { + fprintf(fd, " <SNR>%s()\n", fp->uf_name + 3); + } else { + fprintf(fd, " %s()\n", fp->uf_name); + } + } + fprintf(fd, "\n"); +} + +/// Compare function for total time sorting. +static int prof_total_cmp(const void *s1, const void *s2) +{ + ufunc_T *p1 = *(ufunc_T **)s1; + ufunc_T *p2 = *(ufunc_T **)s2; + return profile_cmp(p1->uf_tm_total, p2->uf_tm_total); +} + +/// Compare function for self time sorting. +static int prof_self_cmp(const void *s1, const void *s2) +{ + ufunc_T *p1 = *(ufunc_T **)s1; + ufunc_T *p2 = *(ufunc_T **)s2; + return profile_cmp(p1->uf_tm_self, p2->uf_tm_self); +} + +/// Start profiling function "fp". +void func_do_profile(ufunc_T *fp) +{ + int len = fp->uf_lines.ga_len; + + if (!fp->uf_prof_initialized) { + if (len == 0) { + len = 1; // avoid getting error for allocating zero bytes + } + fp->uf_tm_count = 0; + fp->uf_tm_self = profile_zero(); + fp->uf_tm_total = profile_zero(); + + if (fp->uf_tml_count == NULL) { + fp->uf_tml_count = xcalloc((size_t)len, sizeof(int)); + } + + if (fp->uf_tml_total == NULL) { + fp->uf_tml_total = xcalloc((size_t)len, sizeof(proftime_T)); + } + + if (fp->uf_tml_self == NULL) { + fp->uf_tml_self = xcalloc((size_t)len, sizeof(proftime_T)); + } + + fp->uf_tml_idx = -1; + fp->uf_prof_initialized = true; + } + + fp->uf_profiling = true; +} + +/// Prepare profiling for entering a child or something else that is not +/// counted for the script/function itself. +/// Should always be called in pair with prof_child_exit(). +/// +/// @param tm place to store waittime +void prof_child_enter(proftime_T *tm) +{ + funccall_T *fc = get_current_funccal(); + + if (fc != NULL && fc->func->uf_profiling) { + fc->prof_child = profile_start(); + } + + script_prof_save(tm); +} + +/// Take care of time spent in a child. +/// Should always be called after prof_child_enter(). +/// +/// @param tm where waittime was stored +void prof_child_exit(proftime_T *tm) +{ + funccall_T *fc = get_current_funccal(); + + if (fc != NULL && fc->func->uf_profiling) { + 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); +} + +/// Called when starting to read a function line. +/// "sourcing_lnum" must be correct! +/// When skipping lines it may not actually be executed, but we won't find out +/// until later and we need to store the time now. +void func_line_start(void *cookie) +{ + funccall_T *fcp = (funccall_T *)cookie; + ufunc_T *fp = fcp->func; + + if (fp->uf_profiling && sourcing_lnum >= 1 + && sourcing_lnum <= fp->uf_lines.ga_len) { + fp->uf_tml_idx = sourcing_lnum - 1; + // Skip continuation lines. + while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL) { + fp->uf_tml_idx--; + } + fp->uf_tml_execed = false; + fp->uf_tml_start = profile_start(); + fp->uf_tml_children = profile_zero(); + fp->uf_tml_wait = profile_get_wait(); + } +} + +/// Called when actually executing a function line. +void func_line_exec(void *cookie) +{ + funccall_T *fcp = (funccall_T *)cookie; + ufunc_T *fp = fcp->func; + + if (fp->uf_profiling && fp->uf_tml_idx >= 0) { + fp->uf_tml_execed = true; + } +} + +/// Called when done with a function line. +void func_line_end(void *cookie) +{ + funccall_T *fcp = (funccall_T *)cookie; + ufunc_T *fp = fcp->func; + + if (fp->uf_profiling && fp->uf_tml_idx >= 0) { + if (fp->uf_tml_execed) { + fp->uf_tml_count[fp->uf_tml_idx]++; + 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; + } +} + +/// Dump the profiling results for all functions in file "fd". +static void func_dump_profile(FILE *fd) +{ + hashtab_T *const functbl = func_tbl_get(); + hashitem_T *hi; + int todo; + ufunc_T *fp; + ufunc_T **sorttab; + int st_len = 0; + + todo = (int)functbl->ht_used; + if (todo == 0) { + return; // nothing to dump + } + + sorttab = xmalloc(sizeof(ufunc_T *) * (size_t)todo); + + for (hi = functbl->ht_array; todo > 0; hi++) { + if (!HASHITEM_EMPTY(hi)) { + todo--; + fp = HI2UF(hi); + if (fp->uf_prof_initialized) { + sorttab[st_len++] = fp; + + if (fp->uf_name[0] == K_SPECIAL) { + fprintf(fd, "FUNCTION <SNR>%s()\n", fp->uf_name + 3); + } else { + fprintf(fd, "FUNCTION %s()\n", fp->uf_name); + } + if (fp->uf_script_ctx.sc_sid != 0) { + bool should_free; + const LastSet last_set = (LastSet){ + .script_ctx = fp->uf_script_ctx, + .channel_id = 0, + }; + char *p = (char *)get_scriptname(last_set, &should_free); + fprintf(fd, " Defined: %s:%" PRIdLINENR "\n", + p, fp->uf_script_ctx.sc_lnum); + if (should_free) { + xfree(p); + } + } + if (fp->uf_tm_count == 1) { + 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, "\n"); + fprintf(fd, "count total (s) self (s)\n"); + + for (int i = 0; i < fp->uf_lines.ga_len; i++) { + if (FUNCLINE(fp, i) == NULL) { + continue; + } + prof_func_line(fd, fp->uf_tml_count[i], + &fp->uf_tml_total[i], &fp->uf_tml_self[i], true); + fprintf(fd, "%s\n", FUNCLINE(fp, i)); + } + fprintf(fd, "\n"); + } + } + } + + if (st_len > 0) { + qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), + prof_total_cmp); + prof_sort_list(fd, sorttab, st_len, "TOTAL", false); + qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), + prof_self_cmp); + prof_sort_list(fd, sorttab, st_len, "SELF", true); + } + + xfree(sorttab); +} + +/// Start profiling a script. +void profile_init(scriptitem_T *si) +{ + si->sn_pr_count = 0; + 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; + si->sn_prof_on = true; + si->sn_pr_nest = 0; +} + +/// Save time when starting to invoke another script or function. +/// +/// @param tm place to store wait time +void script_prof_save(proftime_T *tm) +{ + scriptitem_T *si; + + if (current_sctx.sc_sid > 0 && current_sctx.sc_sid <= script_items.ga_len) { + si = &SCRIPT_ITEM(current_sctx.sc_sid); + if (si->sn_prof_on && si->sn_pr_nest++ == 0) { + si->sn_pr_child = profile_start(); + } + } + *tm = profile_get_wait(); +} + +/// Count time spent in children after invoking another script or function. +void script_prof_restore(proftime_T *tm) +{ + scriptitem_T *si; + + if (current_sctx.sc_sid > 0 && current_sctx.sc_sid <= script_items.ga_len) { + si = &SCRIPT_ITEM(current_sctx.sc_sid); + if (si->sn_prof_on && --si->sn_pr_nest == 0) { + 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); + } + } +} + +/// Dump the profiling results for all scripts in file "fd". +static void script_dump_profile(FILE *fd) +{ + scriptitem_T *si; + FILE *sfd; + sn_prl_T *pp; + + for (int id = 1; id <= script_items.ga_len; id++) { + si = &SCRIPT_ITEM(id); + if (si->sn_prof_on) { + fprintf(fd, "SCRIPT %s\n", si->sn_name); + if (si->sn_pr_count == 1) { + 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, "\n"); + fprintf(fd, "count total (s) self (s)\n"); + + sfd = os_fopen((char *)si->sn_name, "r"); + if (sfd == NULL) { + fprintf(fd, "Cannot open file!\n"); + } else { + // Keep going till the end of file, so that trailing + // continuation lines are listed. + for (int i = 0;; i++) { + if (vim_fgets(IObuff, IOSIZE, sfd)) { + break; + } + // When a line has been truncated, append NL, taking care + // of multi-byte characters . + if (IObuff[IOSIZE - 2] != NUL && IObuff[IOSIZE - 2] != NL) { + int n = IOSIZE - 2; + + // Move to the first byte of this char. + // utf_head_off() doesn't work, because it checks + // for a truncated character. + while (n > 0 && (IObuff[n] & 0xc0) == 0x80) { + n--; + } + + IObuff[n] = NL; + IObuff[n + 1] = NUL; + } + if (i < si->sn_prl_ga.ga_len + && (pp = &PRL_ITEM(si, i))->snp_count > 0) { + fprintf(fd, "%5d ", pp->snp_count); + 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)); + } else { + fprintf(fd, " "); + } + fprintf(fd, "%s", IObuff); + } + fclose(sfd); + } + fprintf(fd, "\n"); + } + } +} + +/// Dump the profiling info. +void profile_dump(void) +{ + FILE *fd; + + if (profile_fname != NULL) { + fd = os_fopen(profile_fname, "w"); + if (fd == NULL) { + semsg(_(e_notopen), profile_fname); + } else { + script_dump_profile(fd); + func_dump_profile(fd); + fclose(fd); + } + } +} + +/// Called when starting to read a script line. +/// "sourcing_lnum" must be correct! +/// When skipping lines it may not actually be executed, but we won't find out +/// until later and we need to store the time now. +void script_line_start(void) +{ + scriptitem_T *si; + sn_prl_T *pp; + + if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) { + return; + } + si = &SCRIPT_ITEM(current_sctx.sc_sid); + if (si->sn_prof_on && sourcing_lnum >= 1) { + // Grow the array before starting the timer, so that the time spent + // here isn't counted. + (void)ga_grow(&si->sn_prl_ga, sourcing_lnum - si->sn_prl_ga.ga_len); + si->sn_prl_idx = sourcing_lnum - 1; + while (si->sn_prl_ga.ga_len <= si->sn_prl_idx + && si->sn_prl_ga.ga_len < si->sn_prl_ga.ga_maxlen) { + // Zero counters for a line that was not used before. + pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len); + pp->snp_count = 0; + pp->sn_prl_total = profile_zero(); + pp->sn_prl_self = profile_zero(); + si->sn_prl_ga.ga_len++; + } + si->sn_prl_execed = false; + si->sn_prl_start = profile_start(); + si->sn_prl_children = profile_zero(); + si->sn_prl_wait = profile_get_wait(); + } +} + +/// Called when actually executing a function line. +void script_line_exec(void) +{ + scriptitem_T *si; + + if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) { + return; + } + si = &SCRIPT_ITEM(current_sctx.sc_sid); + if (si->sn_prof_on && si->sn_prl_idx >= 0) { + si->sn_prl_execed = true; + } +} + +/// Called when done with a function line. +void script_line_end(void) +{ + scriptitem_T *si; + sn_prl_T *pp; + + if (current_sctx.sc_sid <= 0 || current_sctx.sc_sid > script_items.ga_len) { + return; + } + si = &SCRIPT_ITEM(current_sctx.sc_sid); + if (si->sn_prof_on && si->sn_prl_idx >= 0 + && si->sn_prl_idx < si->sn_prl_ga.ga_len) { + if (si->sn_prl_execed) { + pp = &PRL_ITEM(si, si->sn_prl_idx); + pp->snp_count++; + 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; + } +} + /// globals for use in the startuptime related functionality (time_*). static proftime_T g_start_time; static proftime_T g_prev_time; diff --git a/src/nvim/profile.h b/src/nvim/profile.h index 17c35c5eb7..547d11185f 100644 --- a/src/nvim/profile.h +++ b/src/nvim/profile.h @@ -4,7 +4,8 @@ #include <stdint.h> #include <time.h> -typedef uint64_t proftime_T; +#include "nvim/ex_cmds_defs.h" +#include "nvim/runtime.h" #define TIME_MSG(s) do { \ if (time_fd != NULL) time_msg(s, NULL); \ diff --git a/src/nvim/regexp.c b/src/nvim/regexp.c index fbbf904f8b..4f0911af6c 100644 --- a/src/nvim/regexp.c +++ b/src/nvim/regexp.c @@ -28,6 +28,7 @@ #include "nvim/message.h" #include "nvim/os/input.h" #include "nvim/plines.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/strings.h" #include "nvim/vim.h" diff --git a/src/nvim/regexp_defs.h b/src/nvim/regexp_defs.h index 09f244c2f6..b313dfe877 100644 --- a/src/nvim/regexp_defs.h +++ b/src/nvim/regexp_defs.h @@ -15,7 +15,6 @@ #include <stdbool.h> #include "nvim/pos.h" -#include "nvim/profile.h" #include "nvim/types.h" /* diff --git a/src/nvim/runtime.c b/src/nvim/runtime.c index 5d28d624fe..4038e9f78a 100644 --- a/src/nvim/runtime.c +++ b/src/nvim/runtime.c @@ -14,6 +14,7 @@ #include "nvim/lua/executor.h" #include "nvim/option.h" #include "nvim/os/os.h" +#include "nvim/profile.h" #include "nvim/runtime.h" #include "nvim/vim.h" @@ -21,6 +22,8 @@ # include "runtime.c.generated.h" #endif +garray_T script_items = { 0, 0, sizeof(scriptitem_T), 4, NULL }; + static bool runtime_search_path_valid = false; static int *runtime_search_path_ref = NULL; static RuntimeSearchPath runtime_search_path; diff --git a/src/nvim/runtime.h b/src/nvim/runtime.h index d83ec00185..d715dcdf30 100644 --- a/src/nvim/runtime.h +++ b/src/nvim/runtime.h @@ -5,6 +5,31 @@ #include "nvim/ex_docmd.h" +typedef struct scriptitem_S { + char_u *sn_name; + bool sn_prof_on; ///< true when script is/was profiled + bool sn_pr_force; ///< forceit: profile functions in this script + proftime_T sn_pr_child; ///< time set when going into first child + int sn_pr_nest; ///< nesting for sn_pr_child + // profiling the script as a whole + int sn_pr_count; ///< nr of times sourced + proftime_T sn_pr_total; ///< time spent in script + children + proftime_T sn_pr_self; ///< time spent in script itself + proftime_T sn_pr_start; ///< time at script start + proftime_T sn_pr_children; ///< time in children after script start + // profiling the script per line + garray_T sn_prl_ga; ///< things stored for every line + proftime_T sn_prl_start; ///< start time for current line + proftime_T sn_prl_children; ///< time spent in children for this line + proftime_T sn_prl_wait; ///< wait start time for current line + linenr_T sn_prl_idx; ///< index of line being timed; -1 if none + int sn_prl_execed; ///< line being timed was executed +} scriptitem_T; + +/// Growarray to store info about already sourced scripts. +extern garray_T script_items; +#define SCRIPT_ITEM(id) (((scriptitem_T *)script_items.ga_data)[(id) - 1]) + typedef void (*DoInRuntimepathCB)(char *, void *); typedef struct { diff --git a/src/nvim/screen.c b/src/nvim/screen.c index 50bab38f64..0805a11d9f 100644 --- a/src/nvim/screen.c +++ b/src/nvim/screen.c @@ -112,6 +112,7 @@ #include "nvim/path.h" #include "nvim/plines.h" #include "nvim/popupmnu.h" +#include "nvim/profile.h" #include "nvim/quickfix.h" #include "nvim/regexp.h" #include "nvim/screen.h" diff --git a/src/nvim/search.c b/src/nvim/search.c index 4f396505e3..0c557052ed 100644 --- a/src/nvim/search.c +++ b/src/nvim/search.c @@ -43,6 +43,7 @@ #include "nvim/os/input.h" #include "nvim/os/time.h" #include "nvim/path.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/screen.h" #include "nvim/search.h" diff --git a/src/nvim/spell.c b/src/nvim/spell.c index 64139df689..8ae8121e07 100644 --- a/src/nvim/spell.c +++ b/src/nvim/spell.c @@ -107,6 +107,7 @@ #include "nvim/os/os.h" #include "nvim/os_unix.h" #include "nvim/path.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/screen.h" #include "nvim/search.h" diff --git a/src/nvim/syntax.c b/src/nvim/syntax.c index dd3087dd31..10fed63329 100644 --- a/src/nvim/syntax.c +++ b/src/nvim/syntax.c @@ -41,6 +41,7 @@ #include "nvim/os/time.h" #include "nvim/os_unix.h" #include "nvim/path.h" +#include "nvim/profile.h" #include "nvim/regexp.h" #include "nvim/screen.h" #include "nvim/sign.h" diff --git a/src/nvim/types.h b/src/nvim/types.h index 00b9e6fc09..477102276c 100644 --- a/src/nvim/types.h +++ b/src/nvim/types.h @@ -28,6 +28,8 @@ typedef handle_T NS; typedef struct expand expand_T; +typedef uint64_t proftime_T; + typedef enum { kNone = -1, kFalse = 0, |