summaryrefslogtreecommitdiffstats
path: root/src/profiler.c
diff options
context:
space:
mode:
authorDaniel Baumann <daniel.baumann@progress-linux.org>2024-04-07 08:50:31 +0000
committerDaniel Baumann <daniel.baumann@progress-linux.org>2024-04-07 08:50:31 +0000
commitaed8ce9da277f5ecffe968b324f242c41c3b752a (patch)
treed2e538394cb7a8a7c42a4aac6ccf1a8e3256999b /src/profiler.c
parentInitial commit. (diff)
downloadvim-aed8ce9da277f5ecffe968b324f242c41c3b752a.tar.xz
vim-aed8ce9da277f5ecffe968b324f242c41c3b752a.zip
Adding upstream version 2:9.0.1378.upstream/2%9.0.1378upstream
Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>
Diffstat (limited to 'src/profiler.c')
-rw-r--r--src/profiler.c1110
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