Patch 8.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.
Files: runtime/doc/repeat.txt, src/vim9.h, src/vim9compile.c,
src/vim9execute.c, src/userfunc.c, src/proto/vim9compile.pro,
src/structs.h, src/vim9type.c, src/debugger.c, src/ex_cmds.h,
src/ex_docmd.c, src/profiler.c, src/proto/profiler.pro,
src/testdir/test_vim9_disassemble.vim,
src/testdir/test_profile.vim
*** ../vim-8.2.2399/runtime/doc/repeat.txt 2020-06-17 21:47:19.912798036
+0200
--- runtime/doc/repeat.txt 2021-01-23 19:49:22.428623691 +0100
***************
*** 346,351 ****
--- 354,367 ----
Vim version, or update Vim to a newer version. See
|vimscript-version| for what changed between versions.
+ :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.
+ For [noclear] see |vim9-reload|.
+ Without the |+eval| feature this changes the syntax
+ for some commands.
+
*:scr* *:scriptnames*
:scr[iptnames] List all sourced script names, in the order
they were
first sourced. The number is used for the script ID
***************
*** 883,890 ****
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.
Note that functions are first loaded and later executed. When they are loaded
the "file" breakpoints are checked, when they are executed the "func"
--- 899,907 ----
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". 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"
***************
*** 939,948 ****
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.
You can also use the |reltime()| function to measure time. This only requires
! the |+reltime| feature, which is present more often.
For profiling syntax highlighting see |:syntime|.
--- 956,965 ----
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 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 in more builds.
For profiling syntax highlighting see |:syntime|.
***************
*** 989,995 ****
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
numbers prepended for the explanation:
1 FUNCTION Test2() ~
--- 1006,1017 ----
You must always start with a ":profile start fname" command. The resulting
! 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() ~
*** ../vim-8.2.2399/src/vim9.h 2021-01-22 17:51:02.762771043 +0100
--- src/vim9.h 2021-01-23 17:52:56.108568978 +0100
***************
*** 152,157 ****
--- 152,160 ----
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,373 ****
// was compiled.
garray_T df_def_args_isn; // default argument instructions
isn_T *df_instr; // function body to be executed
! int df_instr_count;
int df_varcount; // number of local variables
int df_has_closure; // one if a closure was created
--- 369,380 ----
// 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; // 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
*** ../vim-8.2.2399/src/vim9compile.c 2021-01-22 17:51:02.762771043 +0100
--- src/vim9compile.c 2021-01-24 12:38:22.447219261 +0100
***************
*** 123,128 ****
--- 123,130 ----
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,1698 ****
--- 1695,1723 ----
}
/*
+ * 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,1753 ****
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 ((isn = generate_instr(cctx,
--- 1769,1778 ----
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,2068 ****
--- 2088,2106 ----
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,2583 ****
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;
return generate_PUSHFUNC(cctx, ufunc->uf_name, ufunc->uf_func_type);
}
--- 2613,2622 ----
return FAIL;
// Need to compile any default values to get the argument types.
! 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,3076 ****
clear_tv(&rettv);
// Compile the function into instructions.
! compile_def_function(ufunc, TRUE, cctx);
clear_evalarg(&evalarg, NULL);
--- 3109,3115 ----
clear_tv(&rettv);
// Compile the function into instructions.
! compile_def_function(ufunc, TRUE, cctx->ctx_profiling, cctx);
clear_evalarg(&evalarg, NULL);
***************
*** 5047,5054 ****
r = eap->skip ? OK : FAIL;
goto theend;
}
! if (ufunc->uf_def_status == UF_TO_BE_COMPILED
! && compile_def_function(ufunc, TRUE, cctx) == FAIL)
{
func_ptr_unref(ufunc);
goto theend;
--- 5086,5094 ----
r = eap->skip ? OK : FAIL;
goto theend;
}
! 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,7107 ****
--- 7141,7151 ----
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,7139 ****
--- 7178,7186 ----
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,7806 ****
* 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.
* "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)
{
char_u *line = NULL;
char_u *p;
--- 7841,7858 ----
* 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,
! int profiling,
! cctx_T *outer_cctx)
{
char_u *line = NULL;
char_u *p;
***************
*** 7813,7818 ****
--- 7865,7871 ----
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,7837 ****
--- 7885,7892 ----
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,7953 ****
{
line = next_line_from_context(&cctx, FALSE);
if (cctx.ctx_lnum >= ufunc->uf_lines.ga_len)
// beyond the last line
break;
}
CLEAR_FIELD(ea);
ea.cmdlinep = &line;
ea.cmd = skipwhite(line);
// 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
--- 7987,8021 ----
{
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 '}':
{
// "}" ends a block scope
***************
*** 8308,8315 ****
+ 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;
dfunc->df_varcount = cctx.ctx_locals_count;
dfunc->df_has_closure = cctx.ctx_has_closure;
if (cctx.ctx_outer_used)
--- 8376,8391 ----
+ ufunc->uf_dfunc_idx;
dfunc->df_deleted = FALSE;
dfunc->df_script_seq = current_sctx.sc_seq;
! 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,8591 ****
--- 8662,8669 ----
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:
*** ../vim-8.2.2399/src/vim9execute.c 2021-01-22 20:46:22.775906736 +0100
--- src/vim9execute.c 2021-01-24 12:33:51.332179834 +0100
***************
*** 294,300 ****
// 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);
if (entry != NULL)
{
// Set the script context to the script where the function was defined.
--- 294,300 ----
// 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(ufunc, 1);
if (entry != NULL)
{
// Set the script context to the script where the function was defined.
***************
*** 645,653 ****
int error;
int idx;
int did_emsg_before = did_emsg;
! if (ufunc->uf_def_status == UF_TO_BE_COMPILED
! && compile_def_function(ufunc, FALSE, NULL) == FAIL)
return FAIL;
if (ufunc->uf_def_status == UF_COMPILED)
{
--- 645,654 ----
int error;
int idx;
int did_emsg_before = did_emsg;
+ int profiling = do_profiling == PROF_YES &&
ufunc->uf_profiling;
! if (func_needs_compiling(ufunc, profiling)
! && compile_def_function(ufunc, FALSE, profiling, NULL) == FAIL)
return FAIL;
if (ufunc->uf_def_status == UF_COMPILED)
{
***************
*** 1130,1135 ****
--- 1131,1137 ----
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,1149 ****
#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))
{
if (did_emsg_cumul + did_emsg == did_emsg_before)
semsg(_(e_function_is_not_compiled_str),
--- 1144,1152 ----
#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
! || (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,1161 ****
// Check the function was really compiled.
dfunc_T *dfunc = ((dfunc_T *)def_functions.ga_data)
+ ufunc->uf_dfunc_idx;
! if (dfunc->df_instr == NULL)
{
iemsg("using call_def_function() on not compiled function");
return FAIL;
--- 1158,1164 ----
// Check the function was really compiled.
dfunc_T *dfunc = ((dfunc_T *)def_functions.ga_data)
+ ufunc->uf_dfunc_idx;
! if ((profiling ? dfunc->df_instr_prof : dfunc->df_instr) == NULL)
{
iemsg("using call_def_function() on not compiled function");
return FAIL;
***************
*** 1294,1300 ****
++ectx.ec_stack.ga_len;
}
! ectx.ec_instr = dfunc->df_instr;
}
// Following errors are in the function, not the caller.
--- 1297,1303 ----
++ectx.ec_stack.ga_len;
}
! ectx.ec_instr = profiling ? dfunc->df_instr_prof : dfunc->df_instr;
}
// Following errors are in the function, not the caller.
***************
*** 3495,3500 ****
--- 3498,3523 ----
}
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,3647 ****
--- 3665,3671 ----
ufunc_T *ufunc;
dfunc_T *dfunc;
isn_T *instr;
+ int instr_count;
int current;
int line_idx = 0;
int prev_current = 0;
***************
*** 3677,3684 ****
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)
return;
if (ufunc->uf_def_status != UF_COMPILED)
{
--- 3701,3708 ----
semsg(_(e_cannot_find_function_str), eap->arg);
return;
}
! 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,3698 ****
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)
{
isn_T *iptr = &instr[current];
char *line;
--- 3715,3724 ----
msg((char *)ufunc->uf_name);
dfunc = ((dfunc_T *)def_functions.ga_data) + ufunc->uf_dfunc_idx;
! 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,4324 ****
--- 4345,4358 ----
}
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" : "");
*** ../vim-8.2.2399/src/userfunc.c 2021-01-22 20:46:22.775906736 +0100
--- src/userfunc.c 2021-01-23 22:00:41.710012693 +0100
***************
*** 1601,1612 ****
char_u numbuf[NUMBUFLEN];
char_u *name;
#ifdef FEAT_PROFILE
! proftime_T wait_start;
! proftime_T call_start;
! int started_profiling = FALSE;
#endif
ESTACK_CHECK_DECLARATION
// If depth of calling is getting too high, don't execute the function.
if (funcdepth_increment() == FAIL)
{
--- 1601,1614 ----
char_u numbuf[NUMBUFLEN];
char_u *name;
#ifdef FEAT_PROFILE
! 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,1642 ****
--- 1637,1652 ----
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,1870 ****
--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);
! }
#endif
save_current_sctx = current_sctx;
--- 1859,1865 ----
--no_wait_return;
}
#ifdef FEAT_PROFILE
! profile_may_start_func(&profile_info, fp, fc);
#endif
save_current_sctx = current_sctx;
***************
*** 1902,1921 ****
#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;
! }
#endif
// when being verbose, mention the return value
--- 1897,1903 ----
#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
// when being verbose, mention the return value
***************
*** 1964,1970 ****
current_sctx = save_current_sctx;
#ifdef FEAT_PROFILE
if (do_profiling == PROF_YES)
! script_prof_restore(&wait_start);
#endif
if (using_sandbox)
--sandbox;
--- 1946,1952 ----
current_sctx = save_current_sctx;
#ifdef FEAT_PROFILE
if (do_profiling == PROF_YES)
! script_prof_restore(&profile_info.pi_wait_start);
#endif
if (using_sandbox)
--sandbox;
***************
*** 3982,3988 ****
/*
* :defcompile - compile all :def functions in the current script that need to
! * be compiled. Except dead functions.
*/
void
ex_defcompile(exarg_T *eap UNUSED)
--- 3964,3970 ----
/*
* :defcompile - compile all :def functions in the current script that need to
! * be compiled. Except dead functions. Doesn't do profiling.
*/
void
ex_defcompile(exarg_T *eap UNUSED)
***************
*** 4002,4008 ****
&& ufunc->uf_def_status == UF_TO_BE_COMPILED
&& (ufunc->uf_flags & FC_DEAD) == 0)
{
! compile_def_function(ufunc, FALSE, NULL);
if (func_hashtab.ht_changed != changed)
{
--- 3984,3990 ----
&& ufunc->uf_def_status == UF_TO_BE_COMPILED
&& (ufunc->uf_flags & FC_DEAD) == 0)
{
! compile_def_function(ufunc, FALSE, FALSE, NULL);
if (func_hashtab.ht_changed != changed)
{
***************
*** 4698,4704 ****
SOURCING_LNUM = fcp->linenr;
#ifdef FEAT_PROFILE
if (do_profiling == PROF_YES)
! func_line_start(cookie);
#endif
}
}
--- 4680,4686 ----
SOURCING_LNUM = fcp->linenr;
#ifdef FEAT_PROFILE
if (do_profiling == PROF_YES)
! func_line_start(cookie, SOURCING_LNUM);
#endif
}
}
*** ../vim-8.2.2399/src/proto/vim9compile.pro 2021-01-16 16:06:58.122713790
+0100
--- src/proto/vim9compile.pro 2021-01-23 18:11:31.076723875 +0100
***************
*** 3,8 ****
--- 3,9 ----
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,21 ****
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);
void set_function_type(ufunc_T *ufunc);
void delete_instr(isn_T *isn);
void unlink_def_function(ufunc_T *ufunc);
--- 16,22 ----
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, 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);
*** ../vim-8.2.2399/src/structs.h 2021-01-11 22:16:26.543513760 +0100
--- src/structs.h 2021-01-23 21:36:39.118169567 +0100
***************
*** 1577,1583 ****
#if defined(FEAT_EVAL) || defined(PROTO)
typedef struct funccall_S funccall_T;
! // values used for "uf_dfunc_idx"
typedef enum {
UF_NOT_COMPILED,
UF_TO_BE_COMPILED,
--- 1577,1583 ----
#if defined(FEAT_EVAL) || defined(PROTO)
typedef struct funccall_S funccall_T;
! // values used for "uf_def_status"
typedef enum {
UF_NOT_COMPILED,
UF_TO_BE_COMPILED,
***************
*** 1899,1904 ****
--- 1899,1911 ----
} 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
*** ../vim-8.2.2399/src/vim9type.c 2021-01-16 16:06:58.126713782 +0100
--- src/vim9type.c 2021-01-23 18:17:40.303579040 +0100
***************
*** 336,342 ****
// 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)
return NULL;
if (ufunc->uf_func_type == NULL)
set_function_type(ufunc);
--- 336,343 ----
// 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, FALSE, NULL)
! == FAIL)
return NULL;
if (ufunc->uf_func_type == NULL)
set_function_type(ufunc);
*** ../vim-8.2.2399/src/debugger.c 2020-09-10 19:25:01.612194701 +0200
--- src/debugger.c 2021-01-23 21:08:40.633290192 +0100
***************
*** 864,870 ****
*/
static linenr_T
debuggy_find(
! int 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
--- 864,870 ----
*/
static linenr_T
debuggy_find(
! 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,892 ****
struct debuggy *bp;
int i;
linenr_T lnum = 0;
! char_u *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)
{
name = alloc(STRLEN(fname) + 3);
! if (name == NULL)
! name = fname;
! else
{
STRCPY(name, "<SNR>");
STRCPY(name + 5, fname + 3);
--- 873,897 ----
struct debuggy *bp;
int i;
linenr_T lnum = 0;
! 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;
! // 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)
{
STRCPY(name, "<SNR>");
STRCPY(name + 5, fname + 3);
***************
*** 898,905 ****
// 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 && (
#ifdef FEAT_PROFILE
gap == &prof_ga ||
#endif
--- 903,910 ----
// 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) == is_file
! && bp->dbg_type != DBG_EXPR && (
#ifdef FEAT_PROFILE
gap == &prof_ga ||
#endif
***************
*** 910,916 ****
// 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))
{
lnum = bp->dbg_lnum;
if (fp != NULL)
--- 915,924 ----
// while matching should abort it.
prev_got_int = got_int;
got_int = FALSE;
! 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)
*** ../vim-8.2.2399/src/ex_cmds.h 2021-01-16 20:20:59.646487092 +0100
--- src/ex_cmds.h 2021-01-23 18:43:34.172602715 +0100
***************
*** 489,495 ****
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,
ADDR_NONE),
EXCMD(CMD_djump, "djump", ex_findpat,
EX_BANG|EX_RANGE|EX_DFLALL|EX_WHOLEFOLD|EX_EXTRA,
--- 489,495 ----
EX_BANG|EX_EXTRA|EX_TRLBAR|EX_CMDWIN|EX_LOCK_OK,
ADDR_NONE),
EXCMD(CMD_disassemble, "disassemble", ex_disassemble,
! 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,
*** ../vim-8.2.2399/src/ex_docmd.c 2021-01-23 14:22:10.228667110 +0100
--- src/ex_docmd.c 2021-01-23 22:02:01.437920727 +0100
***************
*** 866,872 ****
if (do_profiling == PROF_YES)
{
if (getline_is_func)
! func_line_start(real_cookie);
else if (getline_equal(fgetline, cookie, getsourceline))
script_line_start();
}
--- 866,872 ----
if (do_profiling == PROF_YES)
{
if (getline_is_func)
! func_line_start(real_cookie, SOURCING_LNUM);
else if (getline_equal(fgetline, cookie, getsourceline))
script_line_start();
}
*** ../vim-8.2.2399/src/profiler.c 2020-08-29 13:39:12.578557657 +0200
--- src/profiler.c 2021-01-23 22:02:10.217909359 +0100
***************
*** 555,560 ****
--- 555,605 ----
}
/*
+ * 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,611 ****
* 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;
--- 642,655 ----
* until later and we need to store the time now.
*/
void
! func_line_start(void *cookie, long lnum)
{
funccall_T *fcp = (funccall_T *)cookie;
ufunc_T *fp = fcp->func;
! if (fp->uf_profiling && lnum >= 1 && lnum <= fp->uf_lines.ga_len)
{
! fp->uf_tml_idx = lnum - 1;
// Skip continuation lines.
while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL)
--fp->uf_tml_idx;
*** ../vim-8.2.2399/src/proto/profiler.pro 2019-12-12 12:55:30.000000000
+0100
--- src/proto/profiler.pro 2021-01-23 22:02:18.893897893 +0100
***************
*** 19,27 ****
void prof_inchar_exit(void);
int prof_def_func(void);
void func_do_profile(ufunc_T *fp);
void prof_child_enter(proftime_T *tm);
void prof_child_exit(proftime_T *tm);
! void func_line_start(void *cookie);
void func_line_exec(void *cookie);
void func_line_end(void *cookie);
void script_do_profile(scriptitem_T *si);
--- 19,29 ----
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, long lnum);
void func_line_exec(void *cookie);
void func_line_end(void *cookie);
void script_do_profile(scriptitem_T *si);
*** ../vim-8.2.2399/src/testdir/test_vim9_disassemble.vim 2021-01-21
20:21:24.244670457 +0100
--- src/testdir/test_vim9_disassemble.vim 2021-01-24 12:44:00.962682393
+0100
***************
*** 1842,1847 ****
--- 1842,1868 ----
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
*** ../vim-8.2.2399/src/testdir/test_profile.vim 2020-08-12
18:50:31.883655785 +0200
--- src/testdir/test_profile.vim 2021-01-24 12:42:26.182355854 +0100
***************
*** 7,28 ****
source screendump.vim
func Test_profile_func()
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
endwhile
sleep 1m
! endfunc
! func! Foo3()
! endfunc
! func! Bar()
! endfunc
call Foo1()
call Foo1()
profile pause
--- 7,33 ----
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*
! XXX Foo1()
! endXXX
! XXX Foo2()
! DDD counter = 100
! while counter > 0
! AAA counter = counter - 1
endwhile
sleep 1m
! endXXX
! XXX Foo3()
! endXXX
! XXX Bar()
! endXXX
call Foo1()
call Foo1()
profile pause
***************
*** 37,42 ****
--- 42,51 ----
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,78 ****
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\+.\+sleep 1m$', lines[19])
call assert_equal('', lines[20])
call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[21])
--- 78,87 ----
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\+.*\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])
*** ../vim-8.2.2399/src/version.c 2021-01-24 11:59:58.075425245 +0100
--- src/version.c 2021-01-24 12:43:19.182419911 +0100
***************
*** 752,753 ****
--- 752,755 ----
{ /* Add new patch number below this line */
+ /**/
+ 2400,
/**/
--
hundred-and-one symptoms of being an internet addict:
221. Your wife melts your keyboard in the oven.
/// Bram Moolenaar -- [email protected] -- http://www.Moolenaar.net \\\
/// sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ \\\
\\\ an exciting new programming language -- http://www.Zimbu.org ///
\\\ help me help AIDS victims -- http://ICCF-Holland.org ///
--
--
You received this message from the "vim_dev" maillist.
Do not top-post! Type your reply below the text you are replying to.
For more information, visit http://www.vim.org/maillist.php
---
You received this message because you are subscribed to the Google Groups
"vim_dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/vim_dev/202101241154.10OBso6P2766756%40masaka.moolenaar.net.
