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.

Author: brammool

src/profiler.c

@@ -558,41 +558,37 @@ 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);
 }
 
 /*
  * 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_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

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);

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

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

src/version.c

@@ -750,6 +750,8 @@ static char *(features[]) =
 
 static int included_patches[] =
 {   /* Add new patch number below this line */
+/**/
+    2530,
 /**/
     2529,
 /**/

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,17 +581,15 @@ 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
 				       + STACK_FRAME_OUTER_OFF)->vval.v_string;
     // 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)
     {