To: vim_dev@googlegroups.com Subject: Patch 8.2.2530 Fcc: outbox From: Bram Moolenaar Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ------------ 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 \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 \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 -- Bram@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 ///