diff options
-rw-r--r-- | src/nvim/eval.c | 49 | ||||
-rw-r--r-- | src/nvim/eval/typval.h | 1 | ||||
-rw-r--r-- | src/nvim/testdir/test_profile.vim | 100 |
3 files changed, 114 insertions, 36 deletions
diff --git a/src/nvim/eval.c b/src/nvim/eval.c index 988435fd19..54c469fabf 100644 --- a/src/nvim/eval.c +++ b/src/nvim/eval.c @@ -5871,10 +5871,6 @@ static int get_lambda_tv(char_u **arg, typval_T *rettv, bool evaluate) fp->uf_scoped = NULL; } - fp->uf_tml_count = NULL; - fp->uf_tml_total = NULL; - fp->uf_tml_self = NULL; - fp->uf_profiling = false; if (prof_def_func()) { func_do_profile(fp); } @@ -21628,25 +21624,29 @@ static void func_do_profile(ufunc_T *fp) { int len = fp->uf_lines.ga_len; - if (len == 0) - len = 1; /* avoid getting error for allocating zero bytes */ - fp->uf_tm_count = 0; - fp->uf_tm_self = profile_zero(); - fp->uf_tm_total = profile_zero(); + if (!fp->uf_prof_initialized) { + if (len == 0) { + len = 1; // avoid getting error for allocating zero bytes + } + fp->uf_tm_count = 0; + fp->uf_tm_self = profile_zero(); + fp->uf_tm_total = profile_zero(); - if (fp->uf_tml_count == NULL) { - fp->uf_tml_count = xcalloc(len, sizeof(int)); - } + if (fp->uf_tml_count == NULL) { + fp->uf_tml_count = xcalloc(len, sizeof(int)); + } - if (fp->uf_tml_total == NULL) { - fp->uf_tml_total = xcalloc(len, sizeof(proftime_T)); - } + if (fp->uf_tml_total == NULL) { + fp->uf_tml_total = xcalloc(len, sizeof(proftime_T)); + } - if (fp->uf_tml_self == NULL) { - fp->uf_tml_self = xcalloc(len, sizeof(proftime_T)); - } + if (fp->uf_tml_self == NULL) { + fp->uf_tml_self = xcalloc(len, sizeof(proftime_T)); + } - fp->uf_tml_idx = -1; + fp->uf_tml_idx = -1; + fp->uf_prof_initialized = true; + } fp->uf_profiling = TRUE; } @@ -21672,7 +21672,7 @@ void func_dump_profile(FILE *fd) if (!HASHITEM_EMPTY(hi)) { --todo; fp = HI2UF(hi); - if (fp->uf_profiling) { + if (fp->uf_prof_initialized) { sorttab[st_len++] = fp; if (fp->uf_name[0] == K_SPECIAL) @@ -22174,6 +22174,7 @@ void call_user_func(ufunc_T *fp, int argcount, typval_T *argvars, char_u *name; proftime_T wait_start; proftime_T call_start; + int started_profiling = false; bool did_save_redo = false; save_redo_T save_redo; @@ -22393,8 +22394,10 @@ void call_user_func(ufunc_T *fp, int argcount, typval_T *argvars, do_profiling_yes && !fp->uf_profiling && has_profiling(false, fp->uf_name, NULL); - if (func_not_yet_profiling_but_should) + if (func_not_yet_profiling_but_should) { + started_profiling = true; func_do_profile(fp); + } bool func_or_func_caller_profiling = do_profiling_yes @@ -22442,6 +22445,10 @@ void call_user_func(ufunc_T *fp, int argcount, typval_T *argvars, fc->caller->func->uf_tml_children = 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; + } } /* when being verbose, mention the return value */ diff --git a/src/nvim/eval/typval.h b/src/nvim/eval/typval.h index e99289c430..5c0f872b38 100644 --- a/src/nvim/eval/typval.h +++ b/src/nvim/eval/typval.h @@ -260,6 +260,7 @@ struct ufunc { garray_T uf_args; ///< arguments garray_T uf_lines; ///< function lines int uf_profiling; ///< true when func is being profiled + int uf_prof_initialized; // Profiling the function as a whole. int uf_tm_count; ///< nr of calls proftime_T uf_tm_total; ///< time spent in function + children diff --git a/src/nvim/testdir/test_profile.vim b/src/nvim/testdir/test_profile.vim index 8996e86b43..1aa4d5eaf8 100644 --- a/src/nvim/testdir/test_profile.vim +++ b/src/nvim/testdir/test_profile.vim @@ -5,6 +5,8 @@ endif func Test_profile_func() let lines = [ + \ 'profile start Xprofile_func.log', + \ 'profile func Foo*"', \ "func! Foo1()", \ "endfunc", \ "func! Foo2()", @@ -33,9 +35,7 @@ func Test_profile_func() call writefile(lines, 'Xprofile_func.vim') call system(v:progpath - \ . ' -es -u NONE -U NONE -i NONE --noplugin' - \ . ' -c "profile start Xprofile_func.log"' - \ . ' -c "profile func Foo*"' + \ . ' -es --clean' \ . ' -c "so Xprofile_func.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) @@ -97,7 +97,7 @@ func Test_profile_file() call writefile(lines, 'Xprofile_file.vim') call system(v:progpath - \ . ' -es -u NONE -U NONE -i NONE --noplugin' + \ . ' -es --clean' \ . ' -c "profile start Xprofile_file.log"' \ . ' -c "profile file Xprofile_file.vim"' \ . ' -c "so Xprofile_file.vim"' @@ -152,17 +152,17 @@ func Test_profile_file_with_cont() let lines = readfile('Xprofile_file.log') call assert_equal(11, len(lines)) - call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) - call assert_equal('Sourced 1 time', lines[1]) - call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) - call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) - call assert_equal('', lines[4]) - call assert_equal('count total (s) self (s)', lines[5]) - call assert_match(' 1 0.\d\+ echo "hello', lines[6]) - call assert_equal(' \ world"', lines[7]) - call assert_match(' 1 0.\d\+ echo "foo ', lines[8]) - call assert_equal(' \bar"', lines[9]) - call assert_equal('', lines[10]) + call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) + call assert_equal('Sourced 1 time', lines[1]) + call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) + call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) + call assert_equal('', lines[4]) + call assert_equal('count total (s) self (s)', lines[5]) + call assert_match(' 1 0.\d\+ echo "hello', lines[6]) + call assert_equal(' \ world"', lines[7]) + call assert_match(' 1 0.\d\+ echo "foo ', lines[8]) + call assert_equal(' \bar"', lines[9]) + call assert_equal('', lines[10]) call delete('Xprofile_file.vim') call delete('Xprofile_file.log') @@ -222,3 +222,73 @@ func Test_profile_truncate_mbyte() call delete('Xprofile_file.vim') call delete('Xprofile_file.log') endfunc + +func Test_profdel_func() + let lines = [ + \ 'profile start Xprofile_file.log', + \ 'func! Foo1()', + \ 'endfunc', + \ 'func! Foo2()', + \ 'endfunc', + \ 'func! Foo3()', + \ 'endfunc', + \ '', + \ 'profile func Foo1', + \ 'profile func Foo2', + \ 'call Foo1()', + \ 'call Foo2()', + \ '', + \ 'profile func Foo3', + \ 'profdel func Foo2', + \ 'profdel func Foo3', + \ 'call Foo1()', + \ 'call Foo2()', + \ 'call Foo3()' ] + call writefile(lines, 'Xprofile_file.vim') + call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') + call assert_equal(0, v:shell_error) + + let lines = readfile('Xprofile_file.log') + call assert_equal(24, len(lines)) + + " Check that: + " - Foo1() is called twice (profdel not invoked) + " - Foo2() is called once (profdel invoked after it was called) + " - Foo3() is not called (profdel invoked before it was called) + call assert_equal('FUNCTION Foo1()', lines[0]) + call assert_equal('Called 2 times', lines[1]) + call assert_equal('FUNCTION Foo2()', lines[7]) + call assert_equal('Called 1 time', lines[8]) + call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[14]) + call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[19]) + + call delete('Xprofile_file.vim') + call delete('Xprofile_file.log') +endfunc + +func Test_profdel_star() + " Foo() is invoked once before and once after 'profdel *'. + " So profiling should report it only once. + let lines = [ + \ 'profile start Xprofile_file.log', + \ 'func! Foo()', + \ 'endfunc', + \ 'profile func Foo', + \ 'call Foo()', + \ 'profdel *', + \ 'call Foo()' ] + call writefile(lines, 'Xprofile_file.vim') + call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') + call assert_equal(0, v:shell_error) + + let lines = readfile('Xprofile_file.log') + call assert_equal(15, len(lines)) + + call assert_equal('FUNCTION Foo()', lines[0]) + call assert_equal('Called 1 time', lines[1]) + call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[7]) + call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[11]) + + call delete('Xprofile_file.vim') + call delete('Xprofile_file.log') +endfunc |