patch 8.2.2400: Vim9: compiled functions are not profiled

Problem:    Vim9: compiled functions are not profiled.
Solution:   Add initial changes to profile compiled functions.  Fix that a
            script-local function was hard to debug.

Author: brammool

runtime/doc/repeat.txt

@@ -1,4 +1,4 @@
-*repeat.txt*    For Vim version 8.2.  Last change: 2021 Jan 02
+*repeat.txt*    For Vim version 8.2.  Last change: 2021 Jan 23
 
 
 		  VIM REFERENCE MANUAL    by Bram Moolenaar
@@ -354,7 +354,7 @@ For writing a Vim script, see chapter 41 of the user manual |usr_41.txt|.
 			Vim version, or update Vim to a newer version.  See
 			|vimscript-version| for what changed between versions.
 
-:vim9script [noclear]				*:vim9* *:vim9script*
+:vim9[script] [noclear]				*:vim9* *:vim9script*
 			Marks a script file as containing |Vim9-script|
 			commands.  Also see |vim9-namespace|.
 			Must be the first command in the file.
@@ -899,8 +899,9 @@ matches ".../plugin/explorer.vim", ".../plugin/iexplorer.vim", etc. >
 matches ".../plugin/explorer.vim" and "explorer.vim" in any other directory.
 
 The match for functions is done against the name as it's shown in the output
-of ":function".  For local functions this means that something like "<SNR>99_"
-is prepended.
+of ":function".  However, for local functions the script-specific prefix such
+as "<SNR>99_" is ignored to make it easier to match script-local functions
+without knowing the ID of the script.
 
 Note that functions are first loaded and later executed.  When they are loaded
 the "file" breakpoints are checked, when they are executed the "func"
@@ -955,10 +956,10 @@ OBSCURE
 
 Profiling means that Vim measures the time that is spent on executing
 functions and/or scripts.  The |+profile| feature is required for this.
-It is only included when Vim was compiled with "huge" features.
+It is included when Vim was compiled with "huge" features.
 
 You can also use the |reltime()| function to measure time.  This only requires
-the |+reltime| feature, which is present more often.
+the |+reltime| feature, which is present in more builds.
 
 For profiling syntax highlighting see |:syntime|.
 
@@ -1005,7 +1006,12 @@ For example, to profile the one_script.vim script file: >
 
 
 You must always start with a ":profile start fname" command.  The resulting
-file is written when Vim exits.  Here is an example of the output, with line
+file is written when Vim exits.  For example, to profile one specific
+function: >
+	profile start /tmp/vimprofile
+	profile func MyFunc
+
+Here is an example of the output, with line
 numbers prepended for the explanation:
 
   1 FUNCTION  Test2() ~

src/debugger.c

@@ -864,7 +864,7 @@ has_profiling(
  */
     static linenr_T
 debuggy_find(
-    int		file,	    // TRUE for a file, FALSE for a function
+    int		is_file,    // TRUE for a file, FALSE for a function
     char_u	*fname,	    // file or function name
     linenr_T	after,	    // after this line number
     garray_T	*gap,	    // either &dbg_breakp or &prof_ga
@@ -873,20 +873,25 @@ debuggy_find(
     struct debuggy *bp;
     int		i;
     linenr_T	lnum = 0;
-    char_u	*name = fname;
+    char_u	*name = NULL;
+    char_u	*short_name = fname;
     int		prev_got_int;
 
     // Return quickly when there are no breakpoints.
     if (gap->ga_len == 0)
 	return (linenr_T)0;
 
-    // Replace K_SNR in function name with "<SNR>".
-    if (!file && fname[0] == K_SPECIAL)
+    // For a script-local function remove the prefix, so that
+    // "profile func Func" matches "Func" in any script.  Otherwise it's very
+    // difficult to profile/debug a script-local function.  It may match a
+    // function in the wrong script, but that is much better than not being
+    // able to profile/debug a function in a script with unknown ID.
+    // Also match a script-specific name.
+    if (!is_file && fname[0] == K_SPECIAL)
     {
+	short_name = vim_strchr(fname, '_') + 1;
 	name = alloc(STRLEN(fname) + 3);
-	if (name == NULL)
-	    name = fname;
-	else
+	if (name != NULL)
 	{
 	    STRCPY(name, "<SNR>");
 	    STRCPY(name + 5, fname + 3);
@@ -898,8 +903,8 @@ debuggy_find(
 	// Skip entries that are not useful or are for a line that is beyond
 	// an already found breakpoint.
 	bp = &DEBUGGY(gap, i);
-	if (((bp->dbg_type == DBG_FILE) == file &&
-		bp->dbg_type != DBG_EXPR && (
+	if (((bp->dbg_type == DBG_FILE) == is_file
+		    && bp->dbg_type != DBG_EXPR && (
 #ifdef FEAT_PROFILE
 		gap == &prof_ga ||
 #endif
@@ -910,7 +915,10 @@ debuggy_find(
 	    // while matching should abort it.
 	    prev_got_int = got_int;
 	    got_int = FALSE;
-	    if (vim_regexec_prog(&bp->dbg_prog, FALSE, name, (colnr_T)0))
+	    if ((name != NULL
+		   && vim_regexec_prog(&bp->dbg_prog, FALSE, name, (colnr_T)0))
+		    || vim_regexec_prog(&bp->dbg_prog, FALSE,
+						       short_name, (colnr_T)0))
 	    {
 		lnum = bp->dbg_lnum;
 		if (fp != NULL)

src/ex_cmds.h

@@ -489,7 +489,7 @@ EXCMD(CMD_digraphs,	"digraphs",	ex_digraphs,
 	EX_BANG|EX_EXTRA|EX_TRLBAR|EX_CMDWIN|EX_LOCK_OK,
 	ADDR_NONE),
 EXCMD(CMD_disassemble,	"disassemble",	ex_disassemble,
-	EX_EXTRA|EX_NEEDARG|EX_TRLBAR|EX_CMDWIN|EX_LOCK_OK,
+	EX_BANG|EX_EXTRA|EX_NEEDARG|EX_TRLBAR|EX_CMDWIN|EX_LOCK_OK,
 	ADDR_NONE),
 EXCMD(CMD_djump,	"djump",	ex_findpat,
 	EX_BANG|EX_RANGE|EX_DFLALL|EX_WHOLEFOLD|EX_EXTRA,

src/ex_docmd.c

@@ -866,7 +866,7 @@ do_cmdline(
 	    if (do_profiling == PROF_YES)
 	    {
 		if (getline_is_func)
-		    func_line_start(real_cookie);
+		    func_line_start(real_cookie, SOURCING_LNUM);
 		else if (getline_equal(fgetline, cookie, getsourceline))
 		    script_line_start();
 	    }

src/profiler.c

@@ -554,6 +554,51 @@ func_do_profile(ufunc_T *fp)
     fp->uf_profiling = TRUE;
 }
 
+/*
+ * When calling a function: may initialize for profiling.
+ */
+    void
+profile_may_start_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc)
+{
+    if (do_profiling == PROF_YES)
+    {
+	if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL))
+	{
+	    info->pi_started_profiling = TRUE;
+	    func_do_profile(fp);
+	}
+	if (fp->uf_profiling
+		    || (fc->caller != NULL && fc->caller->func->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, funccall_T *fc)
+{
+    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 (fc->caller != NULL && fc->caller->func->uf_profiling)
+    {
+	profile_add(&fc->caller->func->uf_tm_children, &info->pi_call_start);
+	profile_add(&fc->caller->func->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.
@@ -597,15 +642,14 @@ prof_child_exit(
  * until later and we need to store the time now.
  */
     void
-func_line_start(void *cookie)
+func_line_start(void *cookie, long lnum)
 {
     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)
+    if (fp->uf_profiling && lnum >= 1 && lnum <= fp->uf_lines.ga_len)
     {
-	fp->uf_tml_idx = SOURCING_LNUM - 1;
+	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;

src/proto/profiler.pro

@@ -19,9 +19,11 @@ void prof_inchar_enter(void);
 void prof_inchar_exit(void);
 int prof_def_func(void);
 void func_do_profile(ufunc_T *fp);
+void profile_may_start_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc);
+void profile_may_end_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc);
 void prof_child_enter(proftime_T *tm);
 void prof_child_exit(proftime_T *tm);
-void func_line_start(void *cookie);
+void func_line_start(void *cookie, long lnum);
 void func_line_exec(void *cookie);
 void func_line_end(void *cookie);
 void script_do_profile(scriptitem_T *si);

src/proto/vim9compile.pro

@@ -3,6 +3,7 @@ int check_defined(char_u *p, size_t len, cctx_T *cctx);
 int check_compare_types(exprtype_T type, typval_T *tv1, typval_T *tv2);
 int use_typecheck(type_T *actual, type_T *expected);
 int need_type(type_T *actual, type_T *expected, int offset, int arg_idx, cctx_T *cctx, int silent, int actual_is_const);
+int func_needs_compiling(ufunc_T *ufunc, int profile);
 int get_script_item_idx(int sid, char_u *name, int check_writable, cctx_T *cctx);
 imported_T *find_imported(char_u *name, size_t len, cctx_T *cctx);
 imported_T *find_imported_in_script(char_u *name, size_t len, int sid);
@@ -15,7 +16,7 @@ void error_white_both(char_u *op, int len);
 int assignment_len(char_u *p, int *heredoc);
 void vim9_declare_error(char_u *name);
 int check_vim9_unlet(char_u *name);
-int compile_def_function(ufunc_T *ufunc, int check_return_type, cctx_T *outer_cctx);
+int compile_def_function(ufunc_T *ufunc, int check_return_type, int profiling, cctx_T *outer_cctx);
 void set_function_type(ufunc_T *ufunc);
 void delete_instr(isn_T *isn);
 void unlink_def_function(ufunc_T *ufunc);

src/structs.h

@@ -1577,7 +1577,7 @@ typedef struct svar_S svar_T;
 #if defined(FEAT_EVAL) || defined(PROTO)
 typedef struct funccall_S funccall_T;
 
-// values used for "uf_dfunc_idx"
+// values used for "uf_def_status"
 typedef enum {
     UF_NOT_COMPILED,
     UF_TO_BE_COMPILED,
@@ -1899,6 +1899,13 @@ typedef struct sn_prl_S
 } sn_prl_T;
 
 #  define PRL_ITEM(si, idx)	(((sn_prl_T *)(si)->sn_prl_ga.ga_data)[(idx)])
+
+typedef struct {
+    int		pi_started_profiling;
+    proftime_T	pi_wait_start;
+    proftime_T	pi_call_start;
+} profinfo_T;
+
 # endif
 #else
 // dummy typedefs for use in function prototypes

src/testdir/test_profile.vim

@@ -7,22 +7,27 @@ source shared.vim
 source screendump.vim
 
 func Test_profile_func()
+  call RunProfileFunc('func', 'let', 'let')
+  call RunProfileFunc('def', 'var', '')
+endfunc
+
+func RunProfileFunc(command, declare, assign)
   let lines =<< trim [CODE]
     profile start Xprofile_func.log
     profile func Foo*
-    func! Foo1()
-    endfunc
-    func! Foo2()
-      let l:count = 100
-      while l:count > 0
-        let l:count = l:count - 1
+    XXX Foo1()
+    endXXX
+    XXX Foo2()
+      DDD counter = 100
+      while counter > 0
+        AAA counter = counter - 1
       endwhile
       sleep 1m
-    endfunc
-    func! Foo3()
-    endfunc
-    func! Bar()
-    endfunc
+    endXXX
+    XXX Foo3()
+    endXXX
+    XXX Bar()
+    endXXX
     call Foo1()
     call Foo1()
     profile pause
@@ -37,6 +42,10 @@ func Test_profile_func()
     delfunc Foo3
   [CODE]
 
+  call map(lines, {k, v -> substitute(v, 'XXX', a:command, '') })
+  call map(lines, {k, v -> substitute(v, 'DDD', a:declare, '') })
+  call map(lines, {k, v -> substitute(v, 'AAA', a:assign, '') })
+
   call writefile(lines, 'Xprofile_func.vim')
   call system(GetVimCommand()
     \ . ' -es --clean'
@@ -69,10 +78,10 @@ func Test_profile_func()
   call assert_match('^ Self time:\s\+\d\+\.\d\+$',                 lines[12])
   call assert_equal('',                                            lines[13])
   call assert_equal('count  total (s)   self (s)',                 lines[14])
-  call assert_match('^\s*1\s\+.*\slet l:count = 100$',             lines[15])
-  call assert_match('^\s*101\s\+.*\swhile l:count > 0$',           lines[16])
-  call assert_match('^\s*100\s\+.*\s  let l:count = l:count - 1$', lines[17])
-  call assert_match('^\s*101\s\+.*\sendwhile$',                    lines[18])
+  call assert_match('^\s*1\s\+.*\s\(let\|var\) counter = 100$',    lines[15])
+  call assert_match('^\s*101\s\+.*\swhile counter > 0$',           lines[16])
+  call assert_match('^\s*100\s\+.*\s  \(let\)\= counter = counter - 1$', lines[17])
+  call assert_match('^\s*10[01]\s\+.*\sendwhile$',                 lines[18])
   call assert_match('^\s*1\s\+.\+sleep 1m$',                       lines[19])
   call assert_equal('',                                            lines[20])
   call assert_equal('FUNCTIONS SORTED ON TOTAL TIME',              lines[21])

src/testdir/test_vim9_disassemble.vim

@@ -1842,6 +1842,27 @@ def Test_silent()
         res)
 enddef
 
+def s:Profiled(): string
+  echo "profiled"
+  return "done"
+enddef
+
+def Test_profiled()
+  var res = execute('disass! s:Profiled')
+  assert_match('<SNR>\d*_Profiled\_s*' ..
+        'echo "profiled"\_s*' ..
+        '\d PROFILE START line 1\_s*' ..
+        '\d PUSHS "profiled"\_s*' ..
+        '\d ECHO 1\_s*' ..
+        '\d PROFILE END\_s*' ..
+        'return "done"\_s*' ..
+        '\d PROFILE START line 2\_s*' ..
+        '\d PUSHS "done"\_s*' ..
+        '\d RETURN\_s*' ..
+        '\d PROFILE END',
+        res)
+enddef
+
 def s:SilentReturn(): string
   silent return "done"
 enddef