Patch 8.2.2530

[Bram Moolenaar]

Patch 8.2.2530
Problem: Vim9: not enough testing for profiling.
Solution: Add a test with nested functions and a lambda. Fix profiling
for calling a compiled function.
Files: src/profiler.c, src/proto/profiler.pro, src/userfunc.c,
src/vim9execute.c, src/testdir/test_profile.vim


*** ../vim-8.2.2529/src/profiler.c 2021-01-24 12:53:30.784247042 +0100
--- src/profiler.c 2021-02-18 21:52:38.477222997 +0100
***************
*** 558,581 ****
* 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);
}
}

/*
--- 558,577 ----
* When calling a function: may initialize for profiling.
*/
void
! profile_may_start_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller)
{
! if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL))
{
! info->pi_started_profiling = TRUE;
! func_do_profile(fp);
}
+ if (fp->uf_profiling || (caller != NULL && caller->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);
}

/*
***************
*** 583,598 ****
* 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
--- 579,594 ----
* must have been called previously.
*/
void
! profile_may_end_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller)
{
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 (caller != NULL && caller->uf_profiling)
{
! profile_add(&caller->uf_tm_children, &info->pi_call_start);
! profile_add(&caller->uf_tml_children, &info->pi_call_start);
}
if (info->pi_started_profiling)
// make a ":profdel func" stop profiling the function
*** ../vim-8.2.2529/src/proto/profiler.pro 2021-01-24 12:53:30.784247042 +0100
--- src/proto/profiler.pro 2021-02-18 21:45:08.638264166 +0100
***************
*** 19,26 ****
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);
--- 19,26 ----
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, ufunc_T *caller);
! void profile_may_end_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller);
void prof_child_enter(proftime_T *tm);
void prof_child_exit(proftime_T *tm);
void func_line_start(void *cookie, long lnum);
*** ../vim-8.2.2529/src/userfunc.c 2021-02-12 22:10:18.227311434 +0100
--- src/userfunc.c 2021-02-18 21:58:28.320397956 +0100
***************
*** 1649,1664 ****

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);
--- 1649,1668 ----

if (fp->uf_def_status != UF_NOT_COMPILED)
{
+ #ifdef FEAT_PROFILE
+ ufunc_T *caller = fc->caller == NULL ? NULL : fc->caller->func;
+ #endif
// Execute the function, possibly compiling it first.
#ifdef FEAT_PROFILE
! if (do_profiling == PROF_YES)
! profile_may_start_func(&profile_info, fp, caller);
#endif
call_def_function(fp, argcount, argvars, funcexe->partial, rettv);
funcdepth_decrement();
#ifdef FEAT_PROFILE
if (do_profiling == PROF_YES && (fp->uf_profiling
! || (caller != NULL && caller->uf_profiling)))
! profile_may_end_func(&profile_info, fp, caller);
#endif
current_funccal = fc->caller;
free_funccal(fc);
***************
*** 1872,1878 ****
--no_wait_return;
}
#ifdef FEAT_PROFILE
! profile_may_start_func(&profile_info, fp, fc);
#endif

save_current_sctx = current_sctx;
--- 1876,1884 ----
--no_wait_return;
}
#ifdef FEAT_PROFILE
! if (do_profiling == PROF_YES)
! profile_may_start_func(&profile_info, fp,
! fc->caller == NULL ? NULL : fc->caller->func);
#endif

save_current_sctx = current_sctx;
***************
*** 1908,1916 ****
}

#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
--- 1914,1926 ----
}

#ifdef FEAT_PROFILE
! if (do_profiling == PROF_YES)
! {
! ufunc_T *caller = fc->caller == NULL ? NULL : fc->caller->func;
!
! if (fp->uf_profiling || (caller != NULL && caller->uf_profiling))
! profile_may_end_func(&profile_info, fp, caller);
! }
#endif

// when being verbose, mention the return value
*** ../vim-8.2.2529/src/vim9execute.c 2021-02-13 18:32:59.264950079 +0100
--- src/vim9execute.c 2021-02-19 18:55:14.966685962 +0100
***************
*** 72,77 ****
--- 72,82 ----
garray_T ec_funcrefs; // partials that might be a closure
};

+ #ifdef FEAT_PROFILE
+ // stack of profinfo_T used when profiling.
+ static garray_T profile_info_ga = {0, 0, sizeof(profinfo_T), 20, NULL};
+ #endif
+
// Get pointer to item relative to the bottom of the stack, -1 is the last one.
#define STACK_TV_BOT(idx) (((typval_T *)ectx->ec_stack.ga_data) + ectx->ec_stack.ga_len + (idx))

***************
*** 184,196 ****
}

#ifdef FEAT_PROFILE
! // Profiling might be enabled/disabled along the way. This should not
! // fail, since the function was compiled before and toggling profiling
! // doesn't change any errors.
! if (func_needs_compiling(ufunc, PROFILING(ufunc))
! && compile_def_function(ufunc, FALSE, PROFILING(ufunc), NULL)
== FAIL)
! return FAIL;
#endif

if (ufunc->uf_va_name != NULL)
--- 189,215 ----
}

#ifdef FEAT_PROFILE
! if (do_profiling == PROF_YES)
! {
! if (ga_grow(&profile_info_ga, 1) == OK)
! {
! profinfo_T *info = ((profinfo_T *)profile_info_ga.ga_data)
! + profile_info_ga.ga_len;
! ++profile_info_ga.ga_len;
! CLEAR_POINTER(info);
! profile_may_start_func(info, ufunc,
! (((dfunc_T *)def_functions.ga_data)
! + ectx->ec_dfunc_idx)->df_ufunc);
! }
!
! // Profiling might be enabled/disabled along the way. This should not
! // fail, since the function was compiled before and toggling profiling
! // doesn't change any errors.
! if (func_needs_compiling(ufunc, PROFILING(ufunc))
! && compile_def_function(ufunc, FALSE, PROFILING(ufunc), NULL)
== FAIL)
! return FAIL;
! }
#endif

if (ufunc->uf_va_name != NULL)
***************
*** 517,523 ****
--- 536,560 ----
int argcount = ufunc_argcount(dfunc->df_ufunc);
int top = ectx->ec_frame_idx - argcount;
estack_T *entry;
+ int prev_dfunc_idx = STACK_TV(ectx->ec_frame_idx
+ + STACK_FRAME_FUNC_OFF)->vval.v_number;
+ dfunc_T *prev_dfunc = ((dfunc_T *)def_functions.ga_data)
+ + prev_dfunc_idx;

+ #ifdef FEAT_PROFILE
+ if (do_profiling == PROF_YES)
+ {
+ ufunc_T *caller = prev_dfunc->df_ufunc;
+
+ if (dfunc->df_ufunc->uf_profiling
+ || (caller != NULL && caller->uf_profiling))
+ {
+ profile_may_end_func(((profinfo_T *)profile_info_ga.ga_data)
+ + profile_info_ga.ga_len - 1, dfunc->df_ufunc, caller);
+ --profile_info_ga.ga_len;
+ }
+ }
+ #endif
// execution context goes one level up
entry = estack_pop();
if (entry != NULL)
***************
*** 544,551 ****
vim_free(ectx->ec_outer);

// Restore the previous frame.
! ectx->ec_dfunc_idx = STACK_TV(ectx->ec_frame_idx
! + STACK_FRAME_FUNC_OFF)->vval.v_number;
ectx->ec_iidx = STACK_TV(ectx->ec_frame_idx
+ STACK_FRAME_IIDX_OFF)->vval.v_number;
ectx->ec_outer = (void *)STACK_TV(ectx->ec_frame_idx
--- 581,587 ----
vim_free(ectx->ec_outer);

// Restore the previous frame.
! ectx->ec_dfunc_idx = prev_dfunc_idx;
ectx->ec_iidx = STACK_TV(ectx->ec_frame_idx
+ STACK_FRAME_IIDX_OFF)->vval.v_number;
ectx->ec_outer = (void *)STACK_TV(ectx->ec_frame_idx
***************
*** 553,560 ****
// restoring ec_frame_idx must be last
ectx->ec_frame_idx = STACK_TV(ectx->ec_frame_idx
+ STACK_FRAME_IDX_OFF)->vval.v_number;
! dfunc = ((dfunc_T *)def_functions.ga_data) + ectx->ec_dfunc_idx;
! ectx->ec_instr = INSTRUCTIONS(dfunc);

if (ret_idx > 0)
{
--- 589,595 ----
// restoring ec_frame_idx must be last
ectx->ec_frame_idx = STACK_TV(ectx->ec_frame_idx
+ STACK_FRAME_IDX_OFF)->vval.v_number;
! ectx->ec_instr = INSTRUCTIONS(prev_dfunc);

if (ret_idx > 0)
{
*** ../vim-8.2.2529/src/testdir/test_profile.vim 2021-01-26 12:06:27.465801087 +0100
--- src/testdir/test_profile.vim 2021-02-19 19:08:59.764522006 +0100
***************
*** 605,609 ****
--- 605,642 ----
call delete('Xprofile_crash.log')
endfunc

+ func Test_vim9_nested_call()
+ let lines =<< trim END
+ vim9script
+ var total = 0
+ def One(Ref: func(number))
+ for i in range(3)
+ Ref(i)
+ endfor
+ enddef
+ def Two(nr: number)
+ total += nr
+ enddef
+ prof start Xprofile_nested.log
+ prof func One
+ prof func Two
+ One((nr) => Two(nr))
+ assert_equal(3, total)
+ END
+ call writefile(lines, 'Xprofile_nested.vim')
+ call system(GetVimCommandClean() . ' -es -c "so Xprofile_nested.vim" -c q')
+ call assert_equal(0, v:shell_error)
+
+ let prof_lines = readfile('Xprofile_nested.log')->join('#')
+ call assert_match('FUNCTION <SNR>\d\+_One().*'
+ \ .. '#Called 1 time.*'
+ \ .. '# 1 \s*[0-9.]\+ for i in range(3)'
+ \ .. '# 3 \s*[0-9.]\+ \s*[0-9.]\+ Ref(i)'
+ \ .. '# 3 \s*[0-9.]\+ endfor', prof_lines)
+ call assert_match('FUNCTION <SNR>\d\+_Two().*'
+ \ .. '#Called 3 times.*'
+ \ .. '# 3 \s*[0-9.]\+ total += nr', prof_lines)
+ endfunc
+

" vim: shiftwidth=2 sts=2 expandtab
*** ../vim-8.2.2529/src/version.c 2021-02-17 21:56:59.909196307 +0100
--- src/version.c 2021-02-18 21:15:08.622333394 +0100
***************
*** 752,753 ****
--- 752,755 ----
{ /* Add new patch number below this line */
+ /**/
+ 2530,
/**/

--
TALL KNIGHT: We are now no longer the Knights Who Say Ni!
ONE KNIGHT: Ni!
OTHERS: Sh!
ONE KNIGHT: (whispers) Sorry.
"Monty Python and the Holy Grail" PYTHON (MONTY) PICTURES LTD

/// Bram Moolenaar -- Br...@Moolenaar.net -- 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 ///