]> granicus.if.org Git - vim/commitdiff
patch 8.2.2400: Vim9: compiled functions are not profiled v8.2.2400
authorBram Moolenaar <Bram@vim.org>
Sun, 24 Jan 2021 11:53:53 +0000 (12:53 +0100)
committerBram Moolenaar <Bram@vim.org>
Sun, 24 Jan 2021 11:53:53 +0000 (12:53 +0100)
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.

16 files changed:
runtime/doc/repeat.txt
src/debugger.c
src/ex_cmds.h
src/ex_docmd.c
src/profiler.c
src/proto/profiler.pro
src/proto/vim9compile.pro
src/structs.h
src/testdir/test_profile.vim
src/testdir/test_vim9_disassemble.vim
src/userfunc.c
src/version.c
src/vim9.h
src/vim9compile.c
src/vim9execute.c
src/vim9type.c

index fc699a1d78d76405fa70edf3b72bc745f85ca684..195a2025a5e206b554b638df2c8a47773b5b9e03 100644 (file)
@@ -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() ~
index f745761f10e4854115da5244696f1c6820dd3375..4e8a1731861642ffaab3e2a7a43eca770ac22925 100644 (file)
@@ -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)
index 30f5221400277ab2f0354d3b6681009b40c002ea..01c6156147809ed7bd9db006bb4632cfce790d6d 100644 (file)
@@ -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,
index b9ae13d0a8d1c816a0a9f058df77cca1467d8bd3..3dec65e88f9541d7b873e57a2f20c1e6695a6a1d 100644 (file)
@@ -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();
            }
index 7896897a44debd5788204bdf5a298a17ae1dd071..46ab3e305917242284dcbd3397983c1f61c1b188 100644 (file)
@@ -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;
index 5e0b6a2144fc953336b7c5a6a1b1d6a03a2dcca9..b2070df132f25236a5c44bab94faaf7b262e6977 100644 (file)
@@ -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);
index d1d1b0c7d0b49ffe3e59e9d5e0e2e1b12caec3fe..04c3c5efda4b2b6319d750b962b4d419a5a732f7 100644 (file)
@@ -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);
index d6bf6672aa34811788dc088c70b18e0d8770b02e..b092b45bb0ecb91386fc0bce32e315f7236ee270 100644 (file)
@@ -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
index 7bac118aeff4d9b7c0f93eed0edbe659ce37672b..9c7cb5cde6f421f18e221a74e73532fc01265f0b 100644 (file)
@@ -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])
index f40bcf0ae025bbe0b6c6d685b9d83ee8cc8caed3..9a3401fc32c34c2c633b35383bcc376761a282aa 100644 (file)
@@ -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
index 5372260d6d423ad5407d78bd290293674dbe3a9b..92166858230060d73d46d0eb9e8bb4e153fcf224 100644 (file)
@@ -1601,12 +1601,14 @@ call_user_func(
     char_u     numbuf[NUMBUFLEN];
     char_u     *name;
 #ifdef FEAT_PROFILE
-    proftime_T wait_start;
-    proftime_T call_start;
-    int                started_profiling = FALSE;
+    profinfo_T profile_info;
 #endif
     ESTACK_CHECK_DECLARATION
 
+#ifdef FEAT_PROFILE
+    CLEAR_FIELD(profile_info);
+#endif
+
     // If depth of calling is getting too high, don't execute the function.
     if (funcdepth_increment() == FAIL)
     {
@@ -1635,8 +1637,16 @@ call_user_func(
     if (fp->uf_def_status != UF_NOT_COMPILED)
     {
        // Execute the function, possibly compiling it first.
+#ifdef FEAT_PROFILE
+       profile_may_start_func(&profile_info, fp, fc);
+#endif
        call_def_function(fp, argcount, argvars, funcexe->partial, rettv);
        funcdepth_decrement();
+#ifdef FEAT_PROFILE
+       if (do_profiling == PROF_YES && (fp->uf_profiling
+                   || (fc->caller != NULL && fc->caller->func->uf_profiling)))
+           profile_may_end_func(&profile_info, fp, fc);
+#endif
        current_funccal = fc->caller;
        free_funccal(fc);
        return;
@@ -1849,22 +1859,7 @@ call_user_func(
        --no_wait_return;
     }
 #ifdef FEAT_PROFILE
-    if (do_profiling == PROF_YES)
-    {
-       if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL))
-       {
-           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(&call_start);
-           profile_zero(&fp->uf_tm_children);
-       }
-       script_prof_save(&wait_start);
-    }
+    profile_may_start_func(&profile_info, fp, fc);
 #endif
 
     save_current_sctx = current_sctx;
@@ -1902,20 +1897,7 @@ call_user_func(
 #ifdef FEAT_PROFILE
     if (do_profiling == PROF_YES && (fp->uf_profiling
                    || (fc->caller != NULL && fc->caller->func->uf_profiling)))
-    {
-       profile_end(&call_start);
-       profile_sub_wait(&wait_start, &call_start);
-       profile_add(&fp->uf_tm_total, &call_start);
-       profile_self(&fp->uf_tm_self, &call_start, &fp->uf_tm_children);
-       if (fc->caller != NULL && fc->caller->func->uf_profiling)
-       {
-           profile_add(&fc->caller->func->uf_tm_children, &call_start);
-           profile_add(&fc->caller->func->uf_tml_children, &call_start);
-       }
-       if (started_profiling)
-           // make a ":profdel func" stop profiling the function
-           fp->uf_profiling = FALSE;
-    }
+       profile_may_end_func(&profile_info, fp, fc);
 #endif
 
     // when being verbose, mention the return value
@@ -1964,7 +1946,7 @@ call_user_func(
     current_sctx = save_current_sctx;
 #ifdef FEAT_PROFILE
     if (do_profiling == PROF_YES)
-       script_prof_restore(&wait_start);
+       script_prof_restore(&profile_info.pi_wait_start);
 #endif
     if (using_sandbox)
        --sandbox;
@@ -3982,7 +3964,7 @@ ex_function(exarg_T *eap)
 
 /*
  * :defcompile - compile all :def functions in the current script that need to
- * be compiled.  Except dead functions.
+ * be compiled.  Except dead functions.  Doesn't do profiling.
  */
     void
 ex_defcompile(exarg_T *eap UNUSED)
@@ -4002,7 +3984,7 @@ ex_defcompile(exarg_T *eap UNUSED)
                    && ufunc->uf_def_status == UF_TO_BE_COMPILED
                    && (ufunc->uf_flags & FC_DEAD) == 0)
            {
-               compile_def_function(ufunc, FALSE, NULL);
+               compile_def_function(ufunc, FALSE, FALSE, NULL);
 
                if (func_hashtab.ht_changed != changed)
                {
@@ -4698,7 +4680,7 @@ get_func_line(
            SOURCING_LNUM = fcp->linenr;
 #ifdef FEAT_PROFILE
            if (do_profiling == PROF_YES)
-               func_line_start(cookie);
+               func_line_start(cookie, SOURCING_LNUM);
 #endif
        }
     }
index 55ce7133b64ec0173534e9de2737ebcb94c66991..41858baacfcdc7c3ad769f1a2458243b8a76056f 100644 (file)
@@ -750,6 +750,8 @@ static char *(features[]) =
 
 static int included_patches[] =
 {   /* Add new patch number below this line */
+/**/
+    2400,
 /**/
     2399,
 /**/
index 8d4faa3d11b505109af19821a17ee7082d40b425..9446c15bf31d95f809ee689fc1a4bdd8a7020703 100644 (file)
@@ -152,6 +152,9 @@ typedef enum {
     ISN_CMDMOD,            // set cmdmod
     ISN_CMDMOD_REV, // undo ISN_CMDMOD
 
+    ISN_PROF_START, // start a line for profiling
+    ISN_PROF_END,   // end a line for profiling
+
     ISN_UNPACK,            // unpack list into items, uses isn_arg.unpack
     ISN_SHUFFLE,    // move item on stack up or down
     ISN_DROP       // pop stack and discard value
@@ -366,8 +369,12 @@ struct dfunc_S {
                                    // was compiled.
 
     garray_T   df_def_args_isn;    // default argument instructions
+
+    // After compiling "df_instr" and/or "df_instr_prof" is not NULL.
     isn_T      *df_instr;          // function body to be executed
-    int                df_instr_count;
+    int                df_instr_count;     // size of "df_instr"
+    isn_T      *df_instr_prof;         // like "df_instr" with profiling
+    int                df_instr_prof_count;    // size of "df_instr_prof"
 
     int                df_varcount;        // number of local variables
     int                df_has_closure;     // one if a closure was created
index ae5cb12f3f7afcb13daedebe1872fa8487a2d341..5a7da1247a7eff912e8797506a73905f6e191668 100644 (file)
@@ -123,6 +123,8 @@ struct cctx_S {
     char_u     *ctx_line_start;    // start of current line or NULL
     garray_T   ctx_instr;          // generated instructions
 
+    int                ctx_profiling;      // when TRUE generate ISN_PROF_START
+
     garray_T   ctx_locals;         // currently visible local variables
     int                ctx_locals_count;   // total number of local variables
 
@@ -1692,6 +1694,29 @@ generate_BLOBAPPEND(cctx_T *cctx)
     return OK;
 }
 
+/*
+ * Return TRUE if "ufunc" should be compiled, taking into account whether
+ * "profile" indicates profiling is to be done.
+ */
+    int
+func_needs_compiling(ufunc_T *ufunc, int profile)
+{
+    switch (ufunc->uf_def_status)
+    {
+       case UF_NOT_COMPILED: return FALSE;
+       case UF_TO_BE_COMPILED: return TRUE;
+       case UF_COMPILED:
+       {
+           dfunc_T *dfunc = ((dfunc_T *)def_functions.ga_data)
+                                                        + ufunc->uf_dfunc_idx;
+
+           return profile ? dfunc->df_instr_prof == NULL
+                          : dfunc->df_instr == NULL;
+       }
+       case UF_COMPILING: return FALSE;
+    }
+}
+
 /*
  * Generate an ISN_DCALL or ISN_UCALL instruction.
  * Return FAIL if the number of arguments is wrong.
@@ -1744,10 +1769,10 @@ generate_CALL(cctx_T *cctx, ufunc_T *ufunc, int pushed_argcount)
                return FAIL;
            }
        }
-       if (ufunc->uf_def_status == UF_TO_BE_COMPILED)
-           if (compile_def_function(ufunc, ufunc->uf_ret_type == NULL, NULL)
-                                                                      == FAIL)
-               return FAIL;
+       if (func_needs_compiling(ufunc, cctx->ctx_profiling)
+               && compile_def_function(ufunc, ufunc->uf_ret_type == NULL,
+                                           cctx->ctx_profiling, NULL) == FAIL)
+           return FAIL;
     }
 
     if ((isn = generate_instr(cctx,
@@ -2063,6 +2088,19 @@ generate_undo_cmdmods(cctx_T *cctx)
     return OK;
 }
 
+    static void
+may_generate_prof_end(cctx_T *cctx, int prof_lnum)
+{
+    if (cctx->ctx_profiling && prof_lnum >= 0)
+    {
+       int save_lnum = cctx->ctx_lnum;
+
+       cctx->ctx_lnum = prof_lnum;
+       generate_instr(cctx, ISN_PROF_END);
+       cctx->ctx_lnum = save_lnum;
+    }
+}
+
 /*
  * Reserve space for a local variable.
  * Return the variable or NULL if it failed.
@@ -2575,9 +2613,10 @@ generate_funcref(cctx_T *cctx, char_u *name)
        return FAIL;
 
     // Need to compile any default values to get the argument types.
-    if (ufunc->uf_def_status == UF_TO_BE_COMPILED)
-       if (compile_def_function(ufunc, TRUE, NULL) == FAIL)
-           return FAIL;
+    if (func_needs_compiling(ufunc, cctx->ctx_profiling)
+           && compile_def_function(ufunc, TRUE, cctx->ctx_profiling, NULL)
+                                                                      == FAIL)
+       return FAIL;
     return generate_PUSHFUNC(cctx, ufunc->uf_name, ufunc->uf_func_type);
 }
 
@@ -3070,7 +3109,7 @@ compile_lambda(char_u **arg, cctx_T *cctx)
     clear_tv(&rettv);
 
     // Compile the function into instructions.
-    compile_def_function(ufunc, TRUE, cctx);
+    compile_def_function(ufunc, TRUE, cctx->ctx_profiling, cctx);
 
     clear_evalarg(&evalarg, NULL);
 
@@ -5047,8 +5086,9 @@ compile_nested_function(exarg_T *eap, cctx_T *cctx)
        r = eap->skip ? OK : FAIL;
        goto theend;
     }
-    if (ufunc->uf_def_status == UF_TO_BE_COMPILED
-           && compile_def_function(ufunc, TRUE, cctx) == FAIL)
+    if (func_needs_compiling(ufunc, cctx->ctx_profiling)
+           && compile_def_function(ufunc, TRUE, cctx->ctx_profiling, cctx)
+                                                                      == FAIL)
     {
        func_ptr_unref(ufunc);
        goto theend;
@@ -7101,7 +7141,11 @@ compile_while(char_u *arg, cctx_T *cctx)
     if (scope == NULL)
        return NULL;
 
+    // "endwhile" jumps back here, one before when profiling
     scope->se_u.se_while.ws_top_label = instr->ga_len;
+    if (cctx->ctx_profiling && ((isn_T *)instr->ga_data)[instr->ga_len - 1]
+                                                  .isn_type == ISN_PROF_START)
+       --scope->se_u.se_while.ws_top_label;
 
     // compile "expr"
     if (compile_expr0(&p, cctx) == FAIL)
@@ -7134,6 +7178,9 @@ compile_endwhile(char_u *arg, cctx_T *cctx)
     cctx->ctx_scope = scope->se_outer;
     unwind_locals(cctx, scope->se_local_count);
 
+    // count the endwhile before jumping
+    may_generate_prof_end(cctx, cctx->ctx_lnum);
+
     // At end of ":for" scope jump back to the FOR instruction.
     generate_JUMP(cctx, JUMP_ALWAYS, scope->se_u.se_while.ws_top_label);
 
@@ -7794,13 +7841,18 @@ add_def_function(ufunc_T *ufunc)
  * When "check_return_type" is set then set ufunc->uf_ret_type to the type of
  * the return statement (used for lambda).  When uf_ret_type is already set
  * then check that it matches.
+ * When "profiling" is true add ISN_PROF_START instructions.
  * "outer_cctx" is set for a nested function.
  * This can be used recursively through compile_lambda(), which may reallocate
  * "def_functions".
  * Returns OK or FAIL.
  */
     int
-compile_def_function(ufunc_T *ufunc, int check_return_type, cctx_T *outer_cctx)
+compile_def_function(
+       ufunc_T     *ufunc,
+       int         check_return_type,
+       int         profiling,
+       cctx_T      *outer_cctx)
 {
     char_u     *line = NULL;
     char_u     *p;
@@ -7813,6 +7865,7 @@ compile_def_function(ufunc_T *ufunc, int check_return_type, cctx_T *outer_cctx)
     int                save_estack_compiling = estack_compiling;
     int                do_estack_push;
     int                new_def_function = FALSE;
+    int                prof_lnum = -1;
 
     // When using a function that was compiled before: Free old instructions.
     // The index is reused.  Otherwise add a new entry in "def_functions".
@@ -7832,6 +7885,8 @@ compile_def_function(ufunc_T *ufunc, int check_return_type, cctx_T *outer_cctx)
     ufunc->uf_def_status = UF_COMPILING;
 
     CLEAR_FIELD(cctx);
+
+    cctx.ctx_profiling = profiling;
     cctx.ctx_ufunc = ufunc;
     cctx.ctx_lnum = -1;
     cctx.ctx_outer = outer_cctx;
@@ -7932,22 +7987,35 @@ compile_def_function(ufunc_T *ufunc, int check_return_type, cctx_T *outer_cctx)
        {
            line = next_line_from_context(&cctx, FALSE);
            if (cctx.ctx_lnum >= ufunc->uf_lines.ga_len)
+           {
                // beyond the last line
+               may_generate_prof_end(&cctx, prof_lnum);
                break;
+           }
        }
 
        CLEAR_FIELD(ea);
        ea.cmdlinep = &line;
        ea.cmd = skipwhite(line);
 
+       if (*ea.cmd == '#')
+       {
+           // "#" starts a comment
+           line = (char_u *)"";
+           continue;
+       }
+
+       if (cctx.ctx_profiling && cctx.ctx_lnum != prof_lnum)
+       {
+           may_generate_prof_end(&cctx, prof_lnum);
+
+           prof_lnum = cctx.ctx_lnum;
+           generate_instr(&cctx, ISN_PROF_START);
+       }
+
        // Some things can be recognized by the first character.
        switch (*ea.cmd)
        {
-           case '#':
-               // "#" starts a comment
-               line = (char_u *)"";
-               continue;
-
            case '}':
                {
                    // "}" ends a block scope
@@ -8308,8 +8376,16 @@ nextline:
                                                         + ufunc->uf_dfunc_idx;
        dfunc->df_deleted = FALSE;
        dfunc->df_script_seq = current_sctx.sc_seq;
-       dfunc->df_instr = instr->ga_data;
-       dfunc->df_instr_count = instr->ga_len;
+       if (cctx.ctx_profiling)
+       {
+           dfunc->df_instr_prof = instr->ga_data;
+           dfunc->df_instr_prof_count = instr->ga_len;
+       }
+       else
+       {
+           dfunc->df_instr = instr->ga_data;
+           dfunc->df_instr_count = instr->ga_len;
+       }
        dfunc->df_varcount = cctx.ctx_locals_count;
        dfunc->df_has_closure = cctx.ctx_has_closure;
        if (cctx.ctx_outer_used)
@@ -8586,6 +8662,8 @@ delete_instr(isn_T *isn)
        case ISN_OPNR:
        case ISN_PCALL:
        case ISN_PCALL_END:
+       case ISN_PROF_END:
+       case ISN_PROF_START:
        case ISN_PUSHBOOL:
        case ISN_PUSHF:
        case ISN_PUSHNR:
index 232c84ed7d530c1ff3ee3c10f80179f922af2c48..e4948859f93a10b4bdff4adf7fedadfd11186f89 100644 (file)
@@ -294,7 +294,7 @@ call_dfunc(int cdf_idx, partial_T *pt, int argcount_arg, ectx_T *ectx)
     // Set execution state to the start of the called function.
     ectx->ec_dfunc_idx = cdf_idx;
     ectx->ec_instr = dfunc->df_instr;
-    entry = estack_push_ufunc(dfunc->df_ufunc, 1);
+    entry = estack_push_ufunc(ufunc, 1);
     if (entry != NULL)
     {
        // Set the script context to the script where the function was defined.
@@ -645,9 +645,10 @@ call_ufunc(
     int                error;
     int                idx;
     int                did_emsg_before = did_emsg;
+    int                profiling = do_profiling == PROF_YES && ufunc->uf_profiling;
 
-    if (ufunc->uf_def_status == UF_TO_BE_COMPILED
-           && compile_def_function(ufunc, FALSE, NULL) == FAIL)
+    if (func_needs_compiling(ufunc, profiling)
+               && compile_def_function(ufunc, FALSE, profiling, NULL) == FAIL)
        return FAIL;
     if (ufunc->uf_def_status == UF_COMPILED)
     {
@@ -1130,6 +1131,7 @@ call_def_function(
     int                save_did_emsg_def = did_emsg_def;
     int                trylevel_at_start = trylevel;
     int                orig_funcdepth;
+    int                profiling = do_profiling == PROF_YES && ufunc->uf_profiling;
 
 // Get pointer to item in the stack.
 #define STACK_TV(idx) (((typval_T *)ectx.ec_stack.ga_data) + idx)
@@ -1142,8 +1144,9 @@ call_def_function(
 #define STACK_TV_VAR(idx) (((typval_T *)ectx.ec_stack.ga_data) + ectx.ec_frame_idx + STACK_FRAME_SIZE + idx)
 
     if (ufunc->uf_def_status == UF_NOT_COMPILED
-           || (ufunc->uf_def_status == UF_TO_BE_COMPILED
-                         && compile_def_function(ufunc, FALSE, NULL) == FAIL))
+           || (func_needs_compiling(ufunc, profiling)
+                        && compile_def_function(ufunc, FALSE, profiling, NULL)
+                                                                     == FAIL))
     {
        if (did_emsg_cumul + did_emsg == did_emsg_before)
            semsg(_(e_function_is_not_compiled_str),
@@ -1155,7 +1158,7 @@ call_def_function(
        // Check the function was really compiled.
        dfunc_T *dfunc = ((dfunc_T *)def_functions.ga_data)
                                                         + ufunc->uf_dfunc_idx;
-       if (dfunc->df_instr == NULL)
+       if ((profiling ? dfunc->df_instr_prof : dfunc->df_instr) == NULL)
        {
            iemsg("using call_def_function() on not compiled function");
            return FAIL;
@@ -1294,7 +1297,7 @@ call_def_function(
            ++ectx.ec_stack.ga_len;
        }
 
-       ectx.ec_instr = dfunc->df_instr;
+       ectx.ec_instr = profiling ? dfunc->df_instr_prof : dfunc->df_instr;
     }
 
     // Following errors are in the function, not the caller.
@@ -3495,6 +3498,26 @@ call_def_function(
                }
                break;
 
+           case ISN_PROF_START:
+           case ISN_PROF_END:
+               {
+                   funccall_T cookie;
+                   ufunc_T         *cur_ufunc =
+                                   (((dfunc_T *)def_functions.ga_data)
+                                                + ectx.ec_dfunc_idx)->df_ufunc;
+
+                   cookie.func = cur_ufunc;
+                   if (iptr->isn_type == ISN_PROF_START)
+                   {
+                       func_line_start(&cookie, iptr->isn_lnum);
+                       // if we get here the instruction is executed
+                       func_line_exec(&cookie);
+                   }
+                   else
+                       func_line_end(&cookie);
+               }
+               break;
+
            case ISN_SHUFFLE:
                {
                    typval_T    tmp_tv;
@@ -3642,6 +3665,7 @@ ex_disassemble(exarg_T *eap)
     ufunc_T    *ufunc;
     dfunc_T    *dfunc;
     isn_T      *instr;
+    int                instr_count;
     int                current;
     int                line_idx = 0;
     int                prev_current = 0;
@@ -3677,8 +3701,8 @@ ex_disassemble(exarg_T *eap)
        semsg(_(e_cannot_find_function_str), eap->arg);
        return;
     }
-    if (ufunc->uf_def_status == UF_TO_BE_COMPILED
-           && compile_def_function(ufunc, FALSE, NULL) == FAIL)
+    if (func_needs_compiling(ufunc, eap->forceit)
+           && compile_def_function(ufunc, FALSE, eap->forceit, NULL) == FAIL)
        return;
     if (ufunc->uf_def_status != UF_COMPILED)
     {
@@ -3691,8 +3715,10 @@ ex_disassemble(exarg_T *eap)
        msg((char *)ufunc->uf_name);
 
     dfunc = ((dfunc_T *)def_functions.ga_data) + ufunc->uf_dfunc_idx;
-    instr = dfunc->df_instr;
-    for (current = 0; current < dfunc->df_instr_count; ++current)
+    instr = eap->forceit ? dfunc->df_instr_prof : dfunc->df_instr;
+    instr_count = eap->forceit ? dfunc->df_instr_prof_count
+                                                      : dfunc->df_instr_count;
+    for (current = 0; current < instr_count; ++current)
     {
        isn_T       *iptr = &instr[current];
        char        *line;
@@ -4319,6 +4345,14 @@ ex_disassemble(exarg_T *eap)
                }
            case ISN_CMDMOD_REV: smsg("%4d CMDMOD_REV", current); break;
 
+           case ISN_PROF_START:
+                smsg("%4d PROFILE START line %d", current, iptr->isn_lnum);
+                break;
+
+           case ISN_PROF_END:
+               smsg("%4d PROFILE END", current);
+               break;
+
            case ISN_UNPACK: smsg("%4d UNPACK %d%s", current,
                        iptr->isn_arg.unpack.unp_count,
                        iptr->isn_arg.unpack.unp_semicolon ? " semicolon" : "");
index 81b0db22dfb15b929e280e4a390cf033770e47b6..1374cee1b148703e2b19ee1fd891537c76960855 100644 (file)
@@ -336,7 +336,8 @@ typval2type_int(typval_T *tv, garray_T *type_gap)
            // May need to get the argument types from default values by
            // compiling the function.
            if (ufunc->uf_def_status == UF_TO_BE_COMPILED
-                           && compile_def_function(ufunc, TRUE, NULL) == FAIL)
+                           && compile_def_function(ufunc, TRUE, FALSE, NULL)
+                                                                      == FAIL)
                return NULL;
            if (ufunc->uf_func_type == NULL)
                set_function_type(ufunc);