diff options
Diffstat (limited to 'src/profiler.c')
| -rw-r--r-- | src/profiler.c | 1110 |
1 files changed, 1110 insertions, 0 deletions
diff --git a/src/profiler.c b/src/profiler.c new file mode 100644 index 0000000..b971cd7 --- /dev/null +++ b/src/profiler.c @@ -0,0 +1,1110 @@ +/* vi:set ts=8 sts=4 sw=4 noet: + * + * VIM - Vi IMproved by Bram Moolenaar + * + * Do ":help uganda" in Vim to read copying and usage conditions. + * Do ":help credits" in Vim to see a list of people who contributed. + * See README.txt for an overview of the Vim source code. + */ + +/* + * profiler.c: vim script profiler + */ + +#include "vim.h" + +#if defined(FEAT_EVAL) || defined(PROTO) +# if defined(FEAT_PROFILE) || defined(FEAT_RELTIME) || defined(PROTO) +/* + * Store the current time in "tm". + */ + void +profile_start(proftime_T *tm) +{ +# ifdef MSWIN + QueryPerformanceCounter(tm); +# else + gettimeofday(tm, NULL); +# endif +} + +/* + * Compute the elapsed time from "tm" till now and store in "tm". + */ + void +profile_end(proftime_T *tm) +{ + proftime_T now; + +# ifdef MSWIN + QueryPerformanceCounter(&now); + tm->QuadPart = now.QuadPart - tm->QuadPart; +# else + 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; + } +# endif +} + +/* + * Subtract the time "tm2" from "tm". + */ + void +profile_sub(proftime_T *tm, proftime_T *tm2) +{ +# ifdef MSWIN + tm->QuadPart -= tm2->QuadPart; +# else + tm->tv_usec -= tm2->tv_usec; + tm->tv_sec -= tm2->tv_sec; + if (tm->tv_usec < 0) + { + tm->tv_usec += 1000000; + --tm->tv_sec; + } +# endif +} + +/* + * Return a string that represents the time in "tm". + * Uses a static buffer! + */ + char * +profile_msg(proftime_T *tm) +{ + static char buf[50]; + +# ifdef MSWIN + LARGE_INTEGER fr; + + QueryPerformanceFrequency(&fr); + sprintf(buf, "%10.6lf", (double)tm->QuadPart / (double)fr.QuadPart); +# else + sprintf(buf, "%3ld.%06ld", (long)tm->tv_sec, (long)tm->tv_usec); +# endif + return buf; +} + +/* + * Return a float that represents the time in "tm". + */ + float_T +profile_float(proftime_T *tm) +{ +# ifdef MSWIN + LARGE_INTEGER fr; + + QueryPerformanceFrequency(&fr); + return (float_T)tm->QuadPart / (float_T)fr.QuadPart; +# else + return (float_T)tm->tv_sec + (float_T)tm->tv_usec / 1000000.0; +# endif +} + +/* + * 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 + { +# ifdef MSWIN + LARGE_INTEGER fr; + + QueryPerformanceCounter(tm); + QueryPerformanceFrequency(&fr); + tm->QuadPart += (LONGLONG)((double)msec / 1000.0 * (double)fr.QuadPart); +# else + long usec; + + gettimeofday(tm, NULL); + usec = (long)tm->tv_usec + (long)msec * 1000; + tm->tv_usec = usec % 1000000L; + tm->tv_sec += usec / 1000000L; +# endif + } +} + +/* + * Return TRUE if the current time is past "tm". + */ + int +profile_passed_limit(proftime_T *tm) +{ + proftime_T now; + +# ifdef MSWIN + if (tm->QuadPart == 0) // timer was not set + return FALSE; + QueryPerformanceCounter(&now); + return (now.QuadPart > tm->QuadPart); +# else + 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)); +# endif +} + +/* + * Set the time in "tm" to zero. + */ + void +profile_zero(proftime_T *tm) +{ +# ifdef MSWIN + tm->QuadPart = 0; +# else + tm->tv_usec = 0; + tm->tv_sec = 0; +# endif +} + +# endif // FEAT_PROFILE || FEAT_RELTIME + +#if defined(FEAT_SYN_HL) && defined(FEAT_RELTIME) && defined(FEAT_PROFILE) +# if defined(HAVE_MATH_H) +# include <math.h> +# endif + +/* + * 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 + { +# ifdef MSWIN + tm2->QuadPart = tm->QuadPart / count; +# else + double usec = (tm->tv_sec * 1000000.0 + tm->tv_usec) / count; + + tm2->tv_sec = floor(usec / 1000000.0); + tm2->tv_usec = vim_round(usec - (tm2->tv_sec * 1000000.0)); +# endif + } +} +#endif + +# if defined(FEAT_PROFILE) || defined(PROTO) +/* + * Functions for profiling. + */ +static proftime_T prof_wait_time; + +/* + * Add the time "tm2" to "tm". + */ + void +profile_add(proftime_T *tm, proftime_T *tm2) +{ +# ifdef MSWIN + tm->QuadPart += tm2->QuadPart; +# else + tm->tv_usec += tm2->tv_usec; + tm->tv_sec += tm2->tv_sec; + if (tm->tv_usec >= 1000000) + { + tm->tv_usec -= 1000000; + ++tm->tv_sec; + } +# endif +} + +/* + * 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. +#ifdef MSWIN + if (total->QuadPart <= children->QuadPart) + return; +#else + if (total->tv_sec < children->tv_sec + || (total->tv_sec == children->tv_sec + && total->tv_usec <= children->tv_usec)) + return; +#endif + profile_add(self, total); + profile_sub(self, children); +} + +/* + * Get the current waittime. + */ + static 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. + */ + static int +profile_equal(proftime_T *tm1, proftime_T *tm2) +{ +# ifdef MSWIN + return (tm1->QuadPart == tm2->QuadPart); +# else + return (tm1->tv_usec == tm2->tv_usec && tm1->tv_sec == tm2->tv_sec); +# endif +} + +/* + * Return <0, 0 or >0 if "tm1" < "tm2", "tm1" == "tm2" or "tm1" > "tm2" + */ + int +profile_cmp(const proftime_T *tm1, const proftime_T *tm2) +{ +# ifdef MSWIN + return (int)(tm2->QuadPart - tm1->QuadPart); +# else + if (tm1->tv_sec == tm2->tv_sec) + return tm2->tv_usec - tm1->tv_usec; + return tm2->tv_sec - tm1->tv_sec; +# endif +} + +static char_u *profile_fname = NULL; +static proftime_T pause_time; + +/* + * Reset all profiling information. + */ + static void +profile_reset(void) +{ + int id; + int todo; + hashtab_T *functbl; + hashitem_T *hi; + + // Reset sourced files. + for (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; + profile_zero(&si->sn_pr_child); + si->sn_pr_nest = 0; + si->sn_pr_count = 0; + profile_zero(&si->sn_pr_total); + profile_zero(&si->sn_pr_self); + profile_zero(&si->sn_pr_start); + profile_zero(&si->sn_pr_children); + ga_clear(&si->sn_prl_ga); + profile_zero(&si->sn_prl_start); + profile_zero(&si->sn_prl_children); + profile_zero(&si->sn_prl_wait); + si->sn_prl_idx = -1; + si->sn_prl_execed = 0; + } + } + + // Reset functions. + functbl = func_tbl_get(); + todo = (int)functbl->ht_used; + + for (hi = functbl->ht_array; todo > 0; ++hi) + { + ufunc_T *fp; + int i; + + if (HASHITEM_EMPTY(hi)) + continue; + + todo--; + fp = HI2UF(hi); + if (fp->uf_prof_initialized) + { + fp->uf_profiling = 0; + fp->uf_prof_initialized = FALSE; + fp->uf_tm_count = 0; + profile_zero(&fp->uf_tm_total); + profile_zero(&fp->uf_tm_self); + profile_zero(&fp->uf_tm_children); + + for (i = 0; i < fp->uf_lines.ga_len; i++) + { + fp->uf_tml_count[i] = 0; + profile_zero(&fp->uf_tml_total[i]); + profile_zero(&fp->uf_tml_self[i]); + } + + profile_zero(&fp->uf_tml_start); + profile_zero(&fp->uf_tml_children); + profile_zero(&fp->uf_tml_wait); + fp->uf_tml_idx = -1; + fp->uf_tml_execed = 0; + } + } + + VIM_CLEAR(profile_fname); +} + +/* + * ":profile cmd args" + */ + void +ex_profile(exarg_T *eap) +{ + char_u *e; + int len; + + e = skiptowhite(eap->arg); + len = (int)(e - eap->arg); + e = skipwhite(e); + + if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) + { + VIM_CLEAR(profile_fname); + profile_fname = expand_env_save_opt(e, TRUE); + do_profiling = PROF_YES; + profile_zero(&prof_wait_time); + set_vim_var_nr(VV_PROFILING, 1L); + } + else if (do_profiling == PROF_NONE) + emsg(_(e_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) + profile_start(&pause_time); + 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); + } + 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[] = { + "start", +#define PROFCMD_START 0 + "stop", +#define PROFCMD_STOP 1 + "pause", +#define PROFCMD_PAUSE 2 + "continue", +#define PROFCMD_CONTINUE 3 + "func", +#define PROFCMD_FUNC 4 + "file", +#define PROFCMD_DUMP 5 + "dump", +#define PROFCMD_FILE 6 + NULL +#define PROFCMD_LAST 7 +}; + +/* + * Function given to ExpandGeneric() to obtain the profile command + * specific expansion. + */ + char_u * +get_profile_name(expand_T *xp UNUSED, int idx) +{ + switch (pexpand_what) + { + case PEXP_SUBCMD: + return (char_u *)pexpand_cmds[idx]; + default: + return NULL; + } +} + +/* + * Handle command line completion for :profile command. + */ + void +set_context_in_profile_cmd(expand_T *xp, char_u *arg) +{ + char_u *end_subcmd; + + // Default: expand subcommands. + xp->xp_context = EXPAND_PROFILE; + pexpand_what = PEXP_SUBCMD; + xp->xp_pattern = arg; + + end_subcmd = skiptowhite(arg); + if (*end_subcmd == NUL) + return; + + if ((end_subcmd - arg == 5 && STRNCMP(arg, "start", 5) == 0) + || (end_subcmd - arg == 4 && STRNCMP(arg, "file", 4) == 0)) + { + xp->xp_context = EXPAND_FILES; + xp->xp_pattern = skipwhite(end_subcmd); + return; + } + else if (end_subcmd - arg == 4 && STRNCMP(arg, "func", 4) == 0) + { + xp->xp_context = EXPAND_USER_FUNC; + xp->xp_pattern = skipwhite(end_subcmd); + return; + } + + 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) +{ + profile_start(&inchar_time); +} + +/* + * Called when finished waiting for the user to type a character. + */ + void +prof_inchar_exit(void) +{ + profile_end(&inchar_time); + profile_add(&prof_wait_time, &inchar_time); +} + + +/* + * Return TRUE when a function defined in the current script should be + * profiled. + */ + int +prof_def_func(void) +{ + 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. + */ + static void +prof_func_line( + FILE *fd, + int count, + proftime_T *total, + proftime_T *self, + int prefer_self) // when equal print only self time +{ + 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, " "); +} + + static void +prof_sort_list( + FILE *fd, + ufunc_T **sorttab, + int st_len, + char *title, + int prefer_self) // when equal print only self time +{ + 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, *p2; + + p1 = *(ufunc_T **)s1; + 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, *p2; + + p1 = *(ufunc_T **)s1; + 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; + profile_zero(&fp->uf_tm_self); + profile_zero(&fp->uf_tm_total); + if (fp->uf_tml_count == NULL) + fp->uf_tml_count = ALLOC_CLEAR_MULT(int, len); + if (fp->uf_tml_total == NULL) + fp->uf_tml_total = ALLOC_CLEAR_MULT(proftime_T, len); + if (fp->uf_tml_self == NULL) + fp->uf_tml_self = ALLOC_CLEAR_MULT(proftime_T, len); + fp->uf_tml_idx = -1; + if (fp->uf_tml_count == NULL || fp->uf_tml_total == NULL + || fp->uf_tml_self == NULL) + return; // out of memory + fp->uf_prof_initialized = TRUE; + } + + fp->uf_profiling = TRUE; +} + +/* + * Save time when starting to invoke another script or function. + */ + static void +script_prof_save( + proftime_T *tm) // place to store wait time +{ + scriptitem_T *si; + + if (SCRIPT_ID_VALID(current_sctx.sc_sid)) + { + si = SCRIPT_ITEM(current_sctx.sc_sid); + if (si->sn_prof_on && si->sn_pr_nest++ == 0) + profile_start(&si->sn_pr_child); + } + profile_get_wait(tm); +} + +/* + * When calling a function: may initialize for profiling. + */ + void +profile_may_start_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller) +{ + if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL)) + { + info->pi_started_profiling = TRUE; + func_do_profile(fp); + } + if (fp->uf_profiling || (caller != NULL && caller->uf_profiling)) + { + ++fp->uf_tm_count; + profile_start(&info->pi_call_start); + profile_zero(&fp->uf_tm_children); + } + script_prof_save(&info->pi_wait_start); +} + +/* + * After calling a function: may handle profiling. profile_may_start_func() + * must have been called previously. + */ + void +profile_may_end_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller) +{ + profile_end(&info->pi_call_start); + profile_sub_wait(&info->pi_wait_start, &info->pi_call_start); + profile_add(&fp->uf_tm_total, &info->pi_call_start); + profile_self(&fp->uf_tm_self, &info->pi_call_start, &fp->uf_tm_children); + if (caller != NULL && caller->uf_profiling) + { + profile_add(&caller->uf_tm_children, &info->pi_call_start); + profile_add(&caller->uf_tml_children, &info->pi_call_start); + } + if (info->pi_started_profiling) + // make a ":profdel func" stop profiling the function + fp->uf_profiling = FALSE; +} + +/* + * 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(). + */ + void +prof_child_enter( + proftime_T *tm) // place to store waittime +{ + funccall_T *fc = get_current_funccal(); + + if (fc != NULL && fc->fc_func->uf_profiling) + profile_start(&fc->fc_prof_child); + script_prof_save(tm); +} + +/* + * Take care of time spent in a child. + * Should always be called after prof_child_enter(). + */ + void +prof_child_exit( + proftime_T *tm) // where waittime was stored +{ + funccall_T *fc = get_current_funccal(); + + if (fc != NULL && fc->fc_func->uf_profiling) + { + profile_end(&fc->fc_prof_child); + profile_sub_wait(tm, &fc->fc_prof_child); // don't count waiting time + profile_add(&fc->fc_func->uf_tm_children, &fc->fc_prof_child); + profile_add(&fc->fc_func->uf_tml_children, &fc->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, long lnum) +{ + funccall_T *fcp = (funccall_T *)cookie; + ufunc_T *fp = fcp->fc_func; + + if (fp->uf_profiling && lnum >= 1 && lnum <= fp->uf_lines.ga_len) + { + fp->uf_tml_idx = 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; + profile_start(&fp->uf_tml_start); + profile_zero(&fp->uf_tml_children); + profile_get_wait(&fp->uf_tml_wait); + } +} + +/* + * Called when actually executing a function line. + */ + void +func_line_exec(void *cookie) +{ + funccall_T *fcp = (funccall_T *)cookie; + ufunc_T *fp = fcp->fc_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->fc_func; + + 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_idx = -1; + } +} + +/* + * Dump the profiling results for all functions in file "fd". + */ + static void +func_dump_profile(FILE *fd) +{ + hashtab_T *functbl; + hashitem_T *hi; + int todo; + ufunc_T *fp; + int i; + ufunc_T **sorttab; + int st_len = 0; + char_u *p; + + functbl = func_tbl_get(); + todo = (int)functbl->ht_used; + if (todo == 0) + return; // nothing to dump + + sorttab = ALLOC_MULT(ufunc_T *, todo); + + for (hi = functbl->ht_array; todo > 0; ++hi) + { + if (!HASHITEM_EMPTY(hi)) + { + --todo; + fp = HI2UF(hi); + if (fp->uf_prof_initialized) + { + if (sorttab != NULL) + 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) + { + p = home_replace_save(NULL, + get_scriptname(fp->uf_script_ctx.sc_sid)); + if (p != NULL) + { + fprintf(fd, " Defined: %s:%ld\n", + p, (long)fp->uf_script_ctx.sc_lnum); + vim_free(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 (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 (sorttab != NULL && 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); + } + + vim_free(sorttab); +} + +/* + * Start profiling script "fp". + */ + void +script_do_profile(scriptitem_T *si) +{ + si->sn_pr_count = 0; + profile_zero(&si->sn_pr_total); + profile_zero(&si->sn_pr_self); + + ga_init2(&si->sn_prl_ga, sizeof(sn_prl_T), 100); + si->sn_prl_idx = -1; + si->sn_prof_on = TRUE; + si->sn_pr_nest = 0; +} + +/* + * Count time spent in children after invoking another script or function. + */ + void +script_prof_restore(proftime_T *tm) +{ + scriptitem_T *si; + + if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) + return; + + si = SCRIPT_ITEM(current_sctx.sc_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); + } +} + +/* + * Dump the profiling results for all scripts in file "fd". + */ + static void +script_dump_profile(FILE *fd) +{ + int id; + scriptitem_T *si; + int i; + FILE *sfd; + sn_prl_T *pp; + + for (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 = mch_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 (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; + + if (enc_utf8) + { + // 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; + } + else if (has_mbyte) + n -= mb_head_off(IObuff, IObuff + 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) + return; + + fd = mch_fopen((char *)profile_fname, "w"); + if (fd == NULL) + semsg(_(e_cant_open_file_str), 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 (!SCRIPT_ID_VALID(current_sctx.sc_sid)) + 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, + (int)(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; + profile_zero(&pp->sn_prl_total); + profile_zero(&pp->sn_prl_self); + ++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); + } +} + +/* + * Called when actually executing a function line. + */ + void +script_line_exec(void) +{ + scriptitem_T *si; + + if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) + 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 script line. + */ + void +script_line_end(void) +{ + scriptitem_T *si; + sn_prl_T *pp; + + if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) + 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; + 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_idx = -1; + } +} +# endif // FEAT_PROFILE + +#endif |