1 files changed, 663 insertions, 1 deletions

diff --git a/src/nvim/profile.c b/src/nvim/profile.c
index fe7bd2e912..d4f3756f4d 100644
--- a/src/nvim/profile.c
+++ b/src/nvim/profile.c
@@ -6,16 +6,32 @@
 #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/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 +211,652 @@ 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;