To: vim_dev@googlegroups.com Subject: Patch 8.2.4712 Fcc: outbox From: Bram Moolenaar Mime-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ------------ Patch 8.2.4712 Problem: Only get profiling information after exiting. Solution: Add "profile dump" and "profile stop". (Marco Hinz, Yegappan Lakshmanan, closes #10107) Files: runtime/doc/repeat.txt, src/profiler.c, src/testdir/test_profile.vim *** ../vim-8.2.4711/runtime/doc/repeat.txt 2022-03-22 12:13:49.147376718 +0000 --- runtime/doc/repeat.txt 2022-04-08 13:21:03.134823741 +0100 *************** *** 1007,1024 **** :prof[ile] start {fname} *:prof* *:profile* *E750* ! Start profiling, write the output in {fname} upon exit. "~/" 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] pause ! 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". :prof[ile] func {pattern} Profile function that matches the pattern {pattern}. --- 1043,1066 ---- :prof[ile] start {fname} *:prof* *:profile* *E750* ! 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 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`. :prof[ile] func {pattern} Profile function that matches the pattern {pattern}. *************** *** 1035,1045 **** after this command. A :profile command in the script itself won't work. :profd[el] ... *:profd* *:profdel* Stop profiling for the arguments specified. See |:breakdel| ! for the arguments. ! You must always start with a ":profile start fname" command. The resulting file is written when Vim exits. For example, to profile one specific --- 1077,1093 ---- 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. 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 *** ../vim-8.2.4711/src/profiler.c 2022-03-15 10:53:01.547462727 +0000 --- src/profiler.c 2022-04-08 13:15:22.031023805 +0100 *************** *** 299,304 **** --- 299,380 ---- 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,319 **** if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) { ! vim_free(profile_fname); profile_fname = expand_env_save_opt(e, TRUE); do_profiling = PROF_YES; profile_zero(&prof_wait_time); --- 389,395 ---- if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) { ! VIM_CLEAR(profile_fname); profile_fname = expand_env_save_opt(e, TRUE); do_profiling = PROF_YES; profile_zero(&prof_wait_time); *************** *** 321,326 **** --- 397,409 ---- } 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,341 **** --- 419,426 ---- } do_profiling = PROF_YES; } + else if (STRCMP(eap->arg, "dump") == 0) + profile_dump(); else { // The rest is similar to ":breakadd". *************** *** 353,368 **** static char *pexpand_cmds[] = { "start", #define PROFCMD_START 0 "pause", ! #define PROFCMD_PAUSE 1 "continue", ! #define PROFCMD_CONTINUE 2 "func", ! #define PROFCMD_FUNC 3 "file", ! #define PROFCMD_FILE 4 NULL ! #define PROFCMD_LAST 5 }; /* --- 438,457 ---- static char *pexpand_cmds[] = { "start", #define PROFCMD_START 0 + "stop", + #define PROFCMD_STOP 1 "pause", ! #define PROFCMD_PAUSE 2 "continue", ! #define PROFCMD_CONTINUE 3 "func", ! #define PROFCMD_FUNC 4 "file", ! #define PROFCMD_DUMP 5 ! "dump", ! #define PROFCMD_FILE 6 NULL ! #define PROFCMD_LAST 7 }; /* *** ../vim-8.2.4711/src/testdir/test_profile.vim 2022-03-15 10:53:01.551462719 +0000 --- src/testdir/test_profile.vim 2022-04-08 13:15:22.031023805 +0100 *************** *** 428,436 **** call delete('Xprofile_file.log') endfunc func Test_profile_completion() call feedkeys(":profile \\\"\", 'tx') ! call assert_equal('"profile continue file func pause start', @:) call feedkeys(":profile start test_prof\\\"\", 'tx') call assert_match('^"profile start.* test_profile\.vim', @:) --- 428,530 ---- 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 \\\"\", 'tx') ! call assert_equal('"profile continue dump file func pause start stop', @:) call feedkeys(":profile start test_prof\\\"\", 'tx') call assert_match('^"profile start.* test_profile\.vim', @:) *************** *** 481,486 **** --- 575,582 ---- 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() *** ../vim-8.2.4711/src/version.c 2022-04-08 11:56:09.179436450 +0100 --- src/version.c 2022-04-08 13:17:11.730967517 +0100 *************** *** 748,749 **** --- 748,751 ---- { /* Add new patch number below this line */ + /**/ + 4712, /**/ -- The chat program is in public domain. This is not the GNU public license. If it breaks then you get to keep both pieces. -- Copyright notice for the chat program /// Bram Moolenaar -- Bram@Moolenaar.net -- http://www.Moolenaar.net \\\ /// \\\ \\\ sponsor Vim, vote for features -- http://www.Vim.org/sponsor/ /// \\\ help me help AIDS victims -- http://ICCF-Holland.org ///