1
0
forked from aniani/vim

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)
This commit is contained in:
Yegappan Lakshmanan
2022-04-08 13:23:19 +01:00
committed by Bram Moolenaar
parent 3a56b6d405
commit 18ee0f603e
4 changed files with 211 additions and 12 deletions

View File

@@ -1043,18 +1043,24 @@ For example, to profile the one_script.vim script file: >
:prof[ile] start {fname} *:prof* *:profile* *E750* :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. "~/" and environment variables in {fname} will be expanded.
If {fname} already exists it will be silently overwritten. If {fname} already exists it will be silently overwritten.
The variable |v:profiling| is set to one. 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 :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 used when doing something that should not be counted (e.g., an
external command). Does not nest. external command). Does not nest.
:prof[ile] continue :prof[ile] continue
Continue profiling after ":profile pause". Continue profiling after `:profile pause`.
:prof[ile] func {pattern} :prof[ile] func {pattern}
Profile function that matches the pattern {pattern}. Profile function that matches the pattern {pattern}.
@@ -1071,11 +1077,17 @@ For example, to profile the one_script.vim script file: >
after this command. A :profile command in the script itself after this command. A :profile command in the script itself
won't work. 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* :profd[el] ... *:profd* *:profdel*
Stop profiling for the arguments specified. See |:breakdel| 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 You must always start with a ":profile start fname" command. The resulting
file is written when Vim exits. For example, to profile one specific file is written when Vim exits. For example, to profile one specific

View File

@@ -298,6 +298,82 @@ profile_cmp(const proftime_T *tm1, const proftime_T *tm2)
static char_u *profile_fname = NULL; static char_u *profile_fname = NULL;
static proftime_T pause_time; 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" * ":profile cmd args"
*/ */
@@ -313,7 +389,7 @@ ex_profile(exarg_T *eap)
if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) 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); profile_fname = expand_env_save_opt(e, TRUE);
do_profiling = PROF_YES; do_profiling = PROF_YES;
profile_zero(&prof_wait_time); profile_zero(&prof_wait_time);
@@ -321,6 +397,13 @@ ex_profile(exarg_T *eap)
} }
else if (do_profiling == PROF_NONE) else if (do_profiling == PROF_NONE)
emsg(_(e_first_use_profile_start_fname)); 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) else if (STRCMP(eap->arg, "pause") == 0)
{ {
if (do_profiling == PROF_YES) if (do_profiling == PROF_YES)
@@ -336,6 +419,8 @@ ex_profile(exarg_T *eap)
} }
do_profiling = PROF_YES; do_profiling = PROF_YES;
} }
else if (STRCMP(eap->arg, "dump") == 0)
profile_dump();
else else
{ {
// The rest is similar to ":breakadd". // The rest is similar to ":breakadd".
@@ -353,16 +438,20 @@ static enum
static char *pexpand_cmds[] = { static char *pexpand_cmds[] = {
"start", "start",
#define PROFCMD_START 0 #define PROFCMD_START 0
"stop",
#define PROFCMD_STOP 1
"pause", "pause",
#define PROFCMD_PAUSE 1 #define PROFCMD_PAUSE 2
"continue", "continue",
#define PROFCMD_CONTINUE 2 #define PROFCMD_CONTINUE 3
"func", "func",
#define PROFCMD_FUNC 3 #define PROFCMD_FUNC 4
"file", "file",
#define PROFCMD_FILE 4 #define PROFCMD_DUMP 5
"dump",
#define PROFCMD_FILE 6
NULL NULL
#define PROFCMD_LAST 5 #define PROFCMD_LAST 7
}; };
/* /*

View File

@@ -428,9 +428,103 @@ func Test_profile_file_with_cont()
call delete('Xprofile_file.log') call delete('Xprofile_file.log')
endfunc 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() func Test_profile_completion()
call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx') 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 feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx')
call assert_match('^"profile start.* test_profile\.vim', @:) 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 func Foo", 'E750:')
call assert_fails("profile pause", 'E750:') call assert_fails("profile pause", 'E750:')
call assert_fails("profile continue", 'E750:') call assert_fails("profile continue", 'E750:')
call assert_fails("profile stop", 'E750:')
call assert_fails("profile dump", 'E750:')
endfunc endfunc
func Test_profile_truncate_mbyte() func Test_profile_truncate_mbyte()

View File

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