Mercurial > vim
diff src/profiler.c @ 17370:ba06a1c42274 v8.1.1684
patch 8.1.1684: profiling functionality is spread out
commit https://github.com/vim/vim/commit/fa55cfc69d2b14761e2a8bd85bc1e0d82df770aa
Author: Bram Moolenaar <Bram@vim.org>
Date: Sat Jul 13 22:59:32 2019 +0200
patch 8.1.1684: profiling functionality is spread out
Problem: Profiling functionality is spread out.
Solution: Put profiling functionality in profiling.c. (Yegappan Lakshmanan,
closes #4666)
author | Bram Moolenaar <Bram@vim.org> |
---|---|
date | Sat, 13 Jul 2019 23:00:06 +0200 |
parents | |
children | 8f44c630c366 |
line wrap: on
line diff
new file mode 100644 --- /dev/null +++ b/src/profiler.c @@ -0,0 +1,679 @@ +/* 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; +} + +# if defined(FEAT_FLOAT) || defined(PROTO) +/* + * 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 +} +# 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_FLOAT) && 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. + */ + 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) +{ +# 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; + +/* + * ":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_free(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(_("E750: First use \":profile start {fname}\"")); + 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 + { + /* 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 + "pause", +#define PROFCMD_PAUSE 1 + "continue", +#define PROFCMD_CONTINUE 2 + "func", +#define PROFCMD_FUNC 3 + "file", +#define PROFCMD_FILE 4 + NULL +#define PROFCMD_LAST 5 +}; + +/* + * 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]; + /* case PEXP_FUNC: TODO */ + 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) + { + xp->xp_context = EXPAND_FILES; + xp->xp_pattern = skipwhite(end_subcmd); + return; + } + + /* TODO: 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 = mch_fopen((char *)profile_fname, "w"); + if (fd == NULL) + semsg(_(e_notopen), profile_fname); + else + { + script_dump_profile(fd); + func_dump_profile(fd); + fclose(fd); + } + } +} + +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; +} + + 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"); +} + +/* + * Print the count and times for one function or function line. + */ + 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, " "); +} + +/* + * Compare function for total time sorting. + */ + 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. + */ + 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; +} + +/* + * 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->func->uf_profiling) + profile_start(&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->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); + } + 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; + 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->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]; + 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; + } +} +# endif /* FEAT_PROFILE */ + +#endif