Mercurial > vim
changeset 28373:2ddf8aa1252c v8.2.4712
patch 8.2.4712: only get profiling information after exiting
Commit: https://github.com/vim/vim/commit/18ee0f603ebd3c091f6d2ab88e652fda32821048
Author: Yegappan Lakshmanan <yegappan@yahoo.com>
Date: Fri Apr 8 13:23:19 2022 +0100
patch 8.2.4712: only get profiling information after exiting
Problem: Only get profiling information after exiting.
Solution: Add "profile dump" and "profile stop". (Marco Hinz, Yegappan
Lakshmanan, closes #10107)
| author | Bram Moolenaar <Bram@vim.org> |
|---|---|
| date | Fri, 08 Apr 2022 14:30:03 +0200 |
| parents | efc1c3dc2b0d |
| children | 14d6f5ebf810 |
| files | runtime/doc/repeat.txt src/profiler.c src/testdir/test_profile.vim src/version.c |
| diffstat | 4 files changed, 211 insertions(+), 12 deletions(-) [+] |
line wrap: on
line diff
--- a/runtime/doc/repeat.txt +++ b/runtime/doc/repeat.txt @@ -1043,18 +1043,24 @@ For example, to profile the one_script.v :prof[ile] start {fname} *:prof* *:profile* *E750* - Start profiling, write the output in {fname} upon exit. + Start profiling, write the output in {fname} upon exit or when + a `:profile stop` or `:profile dump` command is invoked. "~/" and environment variables in {fname} will be expanded. If {fname} already exists it will be silently overwritten. The variable |v:profiling| is set to one. +:prof[ile] stop + Write the collected profiling information to the logfile and + stop profiling. You can use the `:profile start` command to + clear the profiling statistics and start profiling again. + :prof[ile] pause - Don't profile until the following ":profile continue". Can be + Don't profile until the following `:profile continue`. Can be used when doing something that should not be counted (e.g., an external command). Does not nest. :prof[ile] continue - Continue profiling after ":profile pause". + Continue profiling after `:profile pause`. :prof[ile] func {pattern} Profile function that matches the pattern {pattern}. @@ -1071,11 +1077,17 @@ For example, to profile the one_script.v after this command. A :profile command in the script itself won't work. +:prof[ile] dump + Write the current state of profiling to the logfile + immediately. After running this command, Vim continues to + collect the profiling statistics. :profd[el] ... *:profd* *:profdel* Stop profiling for the arguments specified. See |:breakdel| - for the arguments. - + for the arguments. Examples: > + profdel func MyFunc + profdel file MyScript.vim + profdel here You must always start with a ":profile start fname" command. The resulting file is written when Vim exits. For example, to profile one specific
--- a/src/profiler.c +++ b/src/profiler.c @@ -299,6 +299,82 @@ static char_u *profile_fname = NULL; static proftime_T pause_time; /* + * Reset all profiling information. + */ + static void +profile_reset(void) +{ + int id; + int todo; + hashtab_T *functbl; + hashitem_T *hi; + + // Reset sourced files. + for (id = 1; id <= script_items.ga_len; id++) + { + scriptitem_T *si = SCRIPT_ITEM(id); + if (si->sn_prof_on) + { + si->sn_prof_on = FALSE; + si->sn_pr_force = FALSE; + profile_zero(&si->sn_pr_child); + si->sn_pr_nest = 0; + si->sn_pr_count = 0; + profile_zero(&si->sn_pr_total); + profile_zero(&si->sn_pr_self); + profile_zero(&si->sn_pr_start); + profile_zero(&si->sn_pr_children); + ga_clear(&si->sn_prl_ga); + profile_zero(&si->sn_prl_start); + profile_zero(&si->sn_prl_children); + profile_zero(&si->sn_prl_wait); + si->sn_prl_idx = -1; + si->sn_prl_execed = 0; + } + } + + // Reset functions. + functbl = func_tbl_get(); + todo = (int)functbl->ht_used; + + for (hi = functbl->ht_array; todo > 0; ++hi) + { + ufunc_T *fp; + int i; + + if (HASHITEM_EMPTY(hi)) + continue; + + todo--; + fp = HI2UF(hi); + if (fp->uf_prof_initialized) + { + fp->uf_profiling = 0; + fp->uf_prof_initialized = FALSE; + fp->uf_tm_count = 0; + profile_zero(&fp->uf_tm_total); + profile_zero(&fp->uf_tm_self); + profile_zero(&fp->uf_tm_children); + + for (i = 0; i < fp->uf_lines.ga_len; i++) + { + fp->uf_tml_count[i] = 0; + profile_zero(&fp->uf_tml_total[i]); + profile_zero(&fp->uf_tml_self[i]); + } + + profile_zero(&fp->uf_tml_start); + profile_zero(&fp->uf_tml_children); + profile_zero(&fp->uf_tml_wait); + fp->uf_tml_idx = -1; + fp->uf_tml_execed = 0; + } + } + + VIM_CLEAR(profile_fname); +} + +/* * ":profile cmd args" */ void @@ -313,7 +389,7 @@ ex_profile(exarg_T *eap) if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) { - vim_free(profile_fname); + VIM_CLEAR(profile_fname); profile_fname = expand_env_save_opt(e, TRUE); do_profiling = PROF_YES; profile_zero(&prof_wait_time); @@ -321,6 +397,13 @@ ex_profile(exarg_T *eap) } else if (do_profiling == PROF_NONE) emsg(_(e_first_use_profile_start_fname)); + else if (STRCMP(eap->arg, "stop") == 0) + { + profile_dump(); + do_profiling = PROF_NONE; + set_vim_var_nr(VV_PROFILING, 0L); + profile_reset(); + } else if (STRCMP(eap->arg, "pause") == 0) { if (do_profiling == PROF_YES) @@ -336,6 +419,8 @@ ex_profile(exarg_T *eap) } do_profiling = PROF_YES; } + else if (STRCMP(eap->arg, "dump") == 0) + profile_dump(); else { // The rest is similar to ":breakadd". @@ -353,16 +438,20 @@ static enum static char *pexpand_cmds[] = { "start", #define PROFCMD_START 0 + "stop", +#define PROFCMD_STOP 1 "pause", -#define PROFCMD_PAUSE 1 +#define PROFCMD_PAUSE 2 "continue", -#define PROFCMD_CONTINUE 2 +#define PROFCMD_CONTINUE 3 "func", -#define PROFCMD_FUNC 3 +#define PROFCMD_FUNC 4 "file", -#define PROFCMD_FILE 4 +#define PROFCMD_DUMP 5 + "dump", +#define PROFCMD_FILE 6 NULL -#define PROFCMD_LAST 5 +#define PROFCMD_LAST 7 }; /*
--- a/src/testdir/test_profile.vim +++ b/src/testdir/test_profile.vim @@ -428,9 +428,103 @@ func Test_profile_file_with_cont() call delete('Xprofile_file.log') endfunc +" Test for ':profile stop' and ':profile dump' commands +func Test_profile_stop_dump() + call delete('Xprof1.out') + call delete('Xprof2.out') + call delete('Xprof3.out') + func Xprof_test1() + return "Hello" + endfunc + func Xprof_test2() + return "World" + endfunc + + " Test for ':profile stop' + profile start Xprof1.out + profile func Xprof_test1 + call Xprof_test1() + profile stop + + let lines = readfile('Xprof1.out') + call assert_equal(17, len(lines)) + call assert_equal('FUNCTION Xprof_test1()', lines[0]) + call assert_match('Defined:.*test_profile.vim:', lines[1]) + call assert_equal('Called 1 time', lines[2]) + call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) + call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) + call assert_equal('', lines[5]) + call assert_equal('count total (s) self (s)', lines[6]) + call assert_match('^\s*1\s\+.*\sreturn "Hello"$', lines[7]) + call assert_equal('', lines[8]) + call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[9]) + call assert_equal('count total (s) self (s) function', lines[10]) + call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Xprof_test1()$', lines[11]) + call assert_equal('', lines[12]) + call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[13]) + call assert_equal('count total (s) self (s) function', lines[14]) + call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Xprof_test1()$', lines[15]) + call assert_equal('', lines[16]) + + " Test for ':profile stop' for a different function + profile start Xprof2.out + profile func Xprof_test2 + call Xprof_test2() + profile stop + let lines = readfile('Xprof2.out') + call assert_equal(17, len(lines)) + call assert_equal('FUNCTION Xprof_test2()', lines[0]) + call assert_match('Defined:.*test_profile.vim:', lines[1]) + call assert_equal('Called 1 time', lines[2]) + call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) + call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) + call assert_equal('', lines[5]) + call assert_equal('count total (s) self (s)', lines[6]) + call assert_match('^\s*1\s\+.*\sreturn "World"$', lines[7]) + call assert_equal('', lines[8]) + call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[9]) + call assert_equal('count total (s) self (s) function', lines[10]) + call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Xprof_test2()$', lines[11]) + call assert_equal('', lines[12]) + call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[13]) + call assert_equal('count total (s) self (s) function', lines[14]) + call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Xprof_test2()$', lines[15]) + call assert_equal('', lines[16]) + + " Test for ':profile dump' + profile start Xprof3.out + profile func Xprof_test1 + profile func Xprof_test2 + call Xprof_test1() + profile dump + " dump the profile once and verify the contents + let lines = readfile('Xprof3.out') + call assert_equal(17, len(lines)) + call assert_match('^\s*1\s\+.*\sreturn "Hello"$', lines[7]) + call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Xprof_test1()$', lines[11]) + call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Xprof_test1()$', lines[15]) + " dump the profile again and verify the contents + call Xprof_test2() + profile dump + profile stop + let lines = readfile('Xprof3.out') + call assert_equal(28, len(lines)) + call assert_equal('FUNCTION Xprof_test1()', lines[0]) + call assert_match('^\s*1\s\+.*\sreturn "Hello"$', lines[7]) + call assert_equal('FUNCTION Xprof_test2()', lines[9]) + call assert_match('^\s*1\s\+.*\sreturn "World"$', lines[16]) + + delfunc Xprof_test1 + delfunc Xprof_test2 + call delete('Xprof1.out') + call delete('Xprof2.out') + call delete('Xprof3.out') +endfunc + +" Test for :profile sub-command completion func Test_profile_completion() call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx') - call assert_equal('"profile continue file func pause start', @:) + call assert_equal('"profile continue dump file func pause start stop', @:) call feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx') call assert_match('^"profile start.* test_profile\.vim', @:) @@ -481,6 +575,8 @@ func Test_profile_errors() call assert_fails("profile func Foo", 'E750:') call assert_fails("profile pause", 'E750:') call assert_fails("profile continue", 'E750:') + call assert_fails("profile stop", 'E750:') + call assert_fails("profile dump", 'E750:') endfunc func Test_profile_truncate_mbyte()