patch 8.2.2530: Vim9: not enough testing for profiling

Problem:    Vim9: not enough testing for profiling.
Solution:   Add a test with nested functions and a lambda.  Fix profiling
            for calling a compiled function.

diff --git a/src/profiler.c b/src/profiler.c
index 46ab3e305917242284dcbd3397983c1f61c1b188..6f2f2d0a8fdefb6bd800cb841820f6c32f740ce7 100644 (file)
--- a/src/profiler.c
+++ b/src/profiler.c
@@ -558,24 +558,20 @@ 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)
+profile_may_start_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller)
 {
-    if (do_profiling == PROF_YES)
+    if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL))
     {
-       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);
+       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,16 +579,16 @@ profile_may_start_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc)
  * must have been called previously.
  */
     void
-profile_may_end_func(profinfo_T *info, ufunc_T *fp, funccall_T *fc)
+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 (fc->caller != NULL && fc->caller->func->uf_profiling)
+    if (caller != NULL && caller->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);
+       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

diff --git a/src/proto/profiler.pro b/src/proto/profiler.pro
index b2070df132f25236a5c44bab94faaf7b262e6977..1882fbf1088ee6b8f34d6d4b4106dc6ae1ef305c 100644 (file)
--- a/src/proto/profiler.pro
+++ b/src/proto/profiler.pro
@@ -19,8 +19,8 @@ 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 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);

diff --git a/src/testdir/test_profile.vim b/src/testdir/test_profile.vim
index c8c877d5c1e4454bd8344da89cfa4b042f8a00cf..835a60279e916b4dc9364aeda51d54186eefb421 100644 (file)
--- a/src/testdir/test_profile.vim
+++ b/src/testdir/test_profile.vim
@@ -605,5 +605,38 @@ func Test_vim9_profiling()
   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

diff --git a/src/userfunc.c b/src/userfunc.c
index 3e1762189651f8bbf02ca75769896b3ae03335c4..64a8fa6063f0a8bada386f42f96e88496d8e3a5f 100644 (file)
--- a/src/userfunc.c
+++ b/src/userfunc.c
@@ -1649,16 +1649,20 @@ call_user_func(
 
     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
-       profile_may_start_func(&profile_info, fp, fc);
+       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
-                   || (fc->caller != NULL && fc->caller->func->uf_profiling)))
-           profile_may_end_func(&profile_info, fp, fc);
+                                 || (caller != NULL && caller->uf_profiling)))
+           profile_may_end_func(&profile_info, fp, caller);
 #endif
        current_funccal = fc->caller;
        free_funccal(fc);
@@ -1872,7 +1876,9 @@ call_user_func(
        --no_wait_return;
     }
 #ifdef FEAT_PROFILE
-    profile_may_start_func(&profile_info, fp, fc);
+    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,9 +1914,13 @@ call_user_func(
     }
 
 #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);
+    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

diff --git a/src/version.c b/src/version.c
index 68b5ab402bfe6410ec9b84825ece192754f23b96..7e42fa3abb86b2ad8bab87378a61e47fb65abc7c 100644 (file)
--- a/src/version.c
+++ b/src/version.c
@@ -750,6 +750,8 @@ static char *(features[]) =
 
 static int included_patches[] =
 {   /* Add new patch number below this line */
+/**/
+    2530,
 /**/
     2529,
 /**/

diff --git a/src/vim9execute.c b/src/vim9execute.c
index 200139c5b28fd7ef0ae75126d3f29bf0c6c29dcd..fc195337b0fbf386b847a41f08cc4d430bcde233 100644 (file)
--- a/src/vim9execute.c
+++ b/src/vim9execute.c
@@ -72,6 +72,11 @@ struct ectx_S {
     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,13 +189,27 @@ call_dfunc(int cdf_idx, partial_T *pt, int argcount_arg, ectx_T *ectx)
     }
 
 #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)
+    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;
+           return FAIL;
+    }
 #endif
 
     if (ufunc->uf_va_name != NULL)
@@ -517,7 +536,25 @@ func_return(ectx_T *ectx)
     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,8 +581,7 @@ func_return(ectx_T *ectx)
     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_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,8 +589,7 @@ func_return(ectx_T *ectx)
     // 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);
+    ectx->ec_instr = INSTRUCTIONS(prev_dfunc);
 
     if (ret_idx > 0)
     {