diff options
author | Bram Moolenaar <Bram@vim.org> | 2021-01-24 12:53:53 +0100 |
---|---|---|
committer | Bram Moolenaar <Bram@vim.org> | 2021-01-24 12:53:53 +0100 |
commit | b204990346ca857802b174afe8a7fbb05e4f318e (patch) | |
tree | 6660d87cac14e978841c1eaf55994bf8a85f84a9 /src | |
parent | 7cf0c114d690c91ac88c92a1a6f1b1935cb6410f (diff) |
patch 8.2.2400: Vim9: compiled functions are not profiledv8.2.2400
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.
Diffstat (limited to 'src')
-rw-r--r-- | src/debugger.c | 28 | ||||
-rw-r--r-- | src/ex_cmds.h | 2 | ||||
-rw-r--r-- | src/ex_docmd.c | 2 | ||||
-rw-r--r-- | src/profiler.c | 52 | ||||
-rw-r--r-- | src/proto/profiler.pro | 4 | ||||
-rw-r--r-- | src/proto/vim9compile.pro | 3 | ||||
-rw-r--r-- | src/structs.h | 9 | ||||
-rw-r--r-- | src/testdir/test_profile.vim | 39 | ||||
-rw-r--r-- | src/testdir/test_vim9_disassemble.vim | 21 | ||||
-rw-r--r-- | src/userfunc.c | 56 | ||||
-rw-r--r-- | src/version.c | 2 | ||||
-rw-r--r-- | src/vim9.h | 9 | ||||
-rw-r--r-- | src/vim9compile.c | 114 | ||||
-rw-r--r-- | src/vim9execute.c | 56 | ||||
-rw-r--r-- | src/vim9type.c | 3 |
15 files changed, 298 insertions, 102 deletions
diff --git a/src/debugger.c b/src/debugger.c index f745761f10..4e8a173186 100644 --- a/src/debugger.c +++ b/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) diff --git a/src/ex_cmds.h b/src/ex_cmds.h index 30f5221400..01c6156147 100644 --- a/src/ex_cmds.h +++ b/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, diff --git a/src/ex_docmd.c b/src/ex_docmd.c index b9ae13d0a8..3dec65e88f 100644 --- a/src/ex_docmd.c +++ b/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(); } diff --git a/src/profiler.c b/src/profiler.c index 7896897a44..46ab3e3059 100644 --- a/src/profiler.c +++ b/src/profiler.c @@ -555,6 +555,51 @@ func_do_profile(ufunc_T *fp) } /* + * 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. * Should always be called in pair with prof_child_exit(). @@ -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; diff --git a/src/proto/profiler.pro b/src/proto/profiler.pro index 5e0b6a2144..b2070df132 100644 --- a/src/proto/profiler.pro +++ b/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); diff --git a/src/proto/vim9compile.pro b/src/proto/vim9compile.pro index d1d1b0c7d0..04c3c5efda 100644 --- a/src/proto/vim9compile.pro +++ b/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); diff --git a/src/structs.h b/src/structs.h index d6bf6672aa..b092b45bb0 100644 --- a/src/structs.h +++ b/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 diff --git a/src/testdir/test_profile.vim b/src/testdir/test_profile.vim index 7bac118aef..9c7cb5cde6 100644 --- a/src/testdir/test_profile.vim +++ b/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]) diff --git a/src/testdir/test_vim9_disassemble.vim b/src/testdir/test_vim9_disassemble.vim index f40bcf0ae0..9a3401fc32 100644 --- a/src/testdir/test_vim9_disassemble.vim +++ b/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 diff --git a/src/userfunc.c b/src/userfunc.c index 5372260d6d..9216685823 100644 --- a/src/userfunc.c +++ b/src/userfunc.c @@ -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 } } diff --git a/src/version.c b/src/version.c index 55ce7133b6..41858baacf 100644 --- a/src/version.c +++ b/src/version.c @@ -751,6 +751,8 @@ static char *(features[]) = static int included_patches[] = { /* Add new patch number below this line */ /**/ + 2400, +/**/ 2399, /**/ 2398, diff --git a/src/vim9.h b/src/vim9.h index 8d4faa3d11..9446c15bf3 100644 --- a/src/vim9.h +++ b/src/vim9.h @@ -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 diff --git a/src/vim9compile.c b/src/vim9compile.c index ae5cb12f3f..5a7da1247a 100644 --- a/src/vim9compile.c +++ b/src/vim9compile.c @@ -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 @@ -1693,6 +1695,29 @@ generate_BLOBAPPEND(cctx_T *cctx) } /* + * 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: diff --git a/src/vim9execute.c b/src/vim9execute.c index 232c84ed7d..e4948859f9 100644 --- a/src/vim9execute.c +++ b/src/vim9execute.c @@ -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" : ""); diff --git a/src/vim9type.c b/src/vim9type.c index 81b0db22df..1374cee1b1 100644 --- a/src/vim9type.c +++ b/src/vim9type.c @@ -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); |