Merge PR #2427 'Add ":profile dump" and ":profile stop"'

This commit is contained in:
Marco Hinz
2015-11-10 03:09:38 +01:00
5 changed files with 171 additions and 62 deletions

View File

@@ -586,6 +586,9 @@ For example, to profile the one_script.vim script file: >
If {fname} already exists it will be silently overwritten.
The variable |v:profiling| is set to one.
:prof[ile] stop
Write the logfile and stop profiling.
: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
@@ -609,6 +612,9 @@ For example, to profile the one_script.vim script file: >
after this command. A :profile command in the script itself
won't work.
:prof[ile] dump
Don't wait until exiting Vim and write the current state of
profiling to the log immediately.
:profd[el] ... *:profd* *:profdel*
Stop profiling for the arguments specified. See |:breakdel|

View File

@@ -229,50 +229,11 @@ static int echo_attr = 0; /* attributes used for ":echo" */
#define GLV_QUIET TFN_QUIET /* no error messages */
#define GLV_NO_AUTOLOAD TFN_NO_AUTOLOAD /* do not use script autoloading */
/*
* Structure to hold info for a user function.
*/
typedef struct ufunc ufunc_T;
struct ufunc {
int uf_varargs; /* variable nr of arguments */
int uf_flags;
int uf_calls; /* nr of active calls */
garray_T uf_args; /* arguments */
garray_T uf_lines; /* function lines */
int uf_profiling; /* TRUE when func is being profiled */
/* profiling the function as a whole */
int uf_tm_count; /* nr of calls */
proftime_T uf_tm_total; /* time spent in function + children */
proftime_T uf_tm_self; /* time spent in function itself */
proftime_T uf_tm_children; /* time spent in children this call */
/* profiling the function per line */
int *uf_tml_count; /* nr of times line was executed */
proftime_T *uf_tml_total; /* time spent in a line + children */
proftime_T *uf_tml_self; /* time spent in a line itself */
proftime_T uf_tml_start; /* start time for current line */
proftime_T uf_tml_children; /* time spent in children for this line */
proftime_T uf_tml_wait; /* start wait time for current line */
int uf_tml_idx; /* index of line being timed; -1 if none */
int uf_tml_execed; /* line being timed was executed */
scid_T uf_script_ID; /* ID of script where function was defined,
used for s: variables */
int uf_refcount; /* for numbered function: reference count */
char_u uf_name[1]; /* name of function (actually longer); can
start with <SNR>123_ (<SNR> is K_SPECIAL
KS_EXTRA KE_SNR) */
};
/* function flags */
#define FC_ABORT 1 /* abort function on error */
#define FC_RANGE 2 /* function accepts range */
#define FC_DICT 4 /* Dict function, uses "self" */
/*
* All user-defined functions are found in this hashtable.
*/
static hashtab_T func_hashtab;
/* The names of packages that once were loaded are remembered. */
static garray_T ga_loaded = {0, 0, sizeof(char_u *), 4, NULL};
@@ -280,12 +241,6 @@ static garray_T ga_loaded = {0, 0, sizeof(char_u *), 4, NULL};
static dict_T *first_dict = NULL; /* list of all dicts */
static list_T *first_list = NULL; /* list of all lists */
/* From user function to hashitem and back. */
static ufunc_T dumuf;
#define UF2HIKEY(fp) ((fp)->uf_name)
#define HIKEY2UF(p) ((ufunc_T *)(p - (dumuf.uf_name - (char_u *)&dumuf)))
#define HI2UF(hi) HIKEY2UF((hi)->hi_key)
#define FUNCARG(fp, j) ((char_u **)(fp->uf_args.ga_data))[j]
#define FUNCLINE(fp, j) ((char_u **)(fp->uf_lines.ga_data))[j]

View File

@@ -5,6 +5,47 @@
#include "nvim/profile.h"
// All user-defined functions are found in this hashtable.
EXTERN hashtab_T func_hashtab;
// Structure to hold info for a user function.
typedef struct ufunc ufunc_T;
struct ufunc {
int uf_varargs; ///< variable nr of arguments
int uf_flags;
int uf_calls; ///< nr of active calls
garray_T uf_args; ///< arguments
garray_T uf_lines; ///< function lines
int uf_profiling; ///< true when func is being profiled
// Profiling the function as a whole.
int uf_tm_count; ///< nr of calls
proftime_T uf_tm_total; ///< time spent in function + children
proftime_T uf_tm_self; ///< time spent in function itself
proftime_T uf_tm_children; ///< time spent in children this call
// Profiling the function per line.
int *uf_tml_count; ///< nr of times line was executed
proftime_T *uf_tml_total; ///< time spent in a line + children
proftime_T *uf_tml_self; ///< time spent in a line itself
proftime_T uf_tml_start; ///< start time for current line
proftime_T uf_tml_children; ///< time spent in children for this line
proftime_T uf_tml_wait; ///< start wait time for current line
int uf_tml_idx; ///< index of line being timed; -1 if none
int uf_tml_execed; ///< line being timed was executed
scid_T uf_script_ID; ///< ID of script where function was defined,
// used for s: variables
int uf_refcount; ///< for numbered function: reference count
char_u uf_name[1]; ///< name of function (actually longer); can
// start with <SNR>123_ (<SNR> is K_SPECIAL
// KS_EXTRA KE_SNR)
};
// From user function to hashitem and back.
EXTERN ufunc_T dumuf;
#define UF2HIKEY(fp) ((fp)->uf_name)
#define HIKEY2UF(p) ((ufunc_T *)(p - (dumuf.uf_name - (char_u *)&dumuf)))
#define HI2UF(hi) HIKEY2UF((hi)->hi_key)
/* Defines for Vim variables. These must match vimvars[] in eval.c! */
enum {
VV_COUNT,

View File

@@ -761,9 +761,14 @@ void ex_profile(exarg_T *eap)
do_profiling = PROF_YES;
profile_set_wait(profile_zero());
set_vim_var_nr(VV_PROFILING, 1L);
} else if (do_profiling == PROF_NONE)
} else if (do_profiling == PROF_NONE) {
EMSG(_("E750: First use \":profile start {fname}\""));
else if (STRCMP(eap->arg, "pause") == 0) {
} 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)
pause_time = profile_start();
do_profiling = PROF_PAUSED;
@@ -773,6 +778,8 @@ void ex_profile(exarg_T *eap)
profile_set_wait(profile_add(profile_get_wait(), pause_time));
}
do_profiling = PROF_YES;
} else if (STRCMP(eap->arg, "dump") == 0) {
profile_dump();
} else {
/* The rest is similar to ":breakadd". */
ex_breakadd(eap);
@@ -816,18 +823,14 @@ static enum {
} pexpand_what;
static char *pexpand_cmds[] = {
"start",
#define PROFCMD_START 0
"pause",
#define PROFCMD_PAUSE 1
"continue",
#define PROFCMD_CONTINUE 2
"func",
#define PROFCMD_FUNC 3
"dump",
"file",
#define PROFCMD_FILE 4
"func",
"pause",
"start",
"stop",
NULL
#define PROFCMD_LAST 5
};
/*
@@ -890,10 +893,63 @@ void profile_dump(void)
}
}
/*
* Start profiling script "fp".
*/
static void script_do_profile(scriptitem_T *si)
/// Reset all profiling information.
static void profile_reset(void)
{
// Reset sourced files.
for (int id = 1; id <= script_items.ga_len; id++) {
scriptitem_T *si = &SCRIPT_ITEM(id);
if (si->sn_prof_on) {
si->sn_prof_on = 0;
si->sn_pr_force = 0;
si->sn_pr_child = profile_zero();
si->sn_pr_nest = 0;
si->sn_pr_count = 0;
si->sn_pr_total = profile_zero();
si->sn_pr_self = profile_zero();
si->sn_pr_start = profile_zero();
si->sn_pr_children = profile_zero();
ga_clear(&si->sn_prl_ga);
si->sn_prl_start = profile_zero();
si->sn_prl_children = profile_zero();
si->sn_prl_wait = profile_zero();
si->sn_prl_idx = -1;
si->sn_prl_execed = 0;
}
}
// Reset functions.
size_t n = func_hashtab.ht_used;
hashitem_T *hi = func_hashtab.ht_array;
for (; n > (size_t)0; hi++) {
if (!HASHITEM_EMPTY(hi)) {
n--;
ufunc_T *uf = HI2UF(hi);
if (uf->uf_profiling) {
uf->uf_profiling = 0;
uf->uf_tm_count = 0;
uf->uf_tm_total = profile_zero();
uf->uf_tm_self = profile_zero();
uf->uf_tm_children = profile_zero();
uf->uf_tml_count = NULL;
uf->uf_tml_total = NULL;
uf->uf_tml_self = NULL;
uf->uf_tml_start = profile_zero();
uf->uf_tml_children = profile_zero();
uf->uf_tml_wait = profile_zero();
uf->uf_tml_idx = -1;
uf->uf_tml_execed = 0;
}
}
}
xfree(profile_fname);
profile_fname = NULL;
}
/// Start profiling a script.
static void profile_init(scriptitem_T *si)
{
si->sn_pr_count = 0;
si->sn_pr_total = profile_zero();
@@ -2509,8 +2565,8 @@ do_source (
int forceit;
/* Check if we do profiling for this script. */
if (!si->sn_prof_on && has_profiling(TRUE, si->sn_name, &forceit)) {
script_do_profile(si);
if (!si->sn_prof_on && has_profiling(true, si->sn_name, &forceit)) {
profile_init(si);
si->sn_pr_force = forceit;
}
if (si->sn_prof_on) {

View File

@@ -0,0 +1,51 @@
require('os')
require('lfs')
local helpers = require('test.functional.helpers')
local eval = helpers.eval
local command = helpers.command
local eq, neq = helpers.eq, helpers.neq
local tempfile = os.tmpname()
-- os.tmpname() also creates the file on POSIX systems. Remove it again.
-- We just need the name, ignoring any race conditions.
if lfs.attributes(tempfile, 'uid') then
os.remove(tempfile)
end
local function assert_file_exists(filepath)
-- Use 2-argument lfs.attributes() so no extra table gets created.
-- We don't really care for the uid.
neq(nil, lfs.attributes(filepath, 'uid'))
end
local function assert_file_exists_not(filepath)
eq(nil, lfs.attributes(filepath, 'uid'))
end
describe(':profile', function()
before_each(helpers.clear)
after_each(function()
if lfs.attributes(tempfile, 'uid') ~= nil then
os.remove(tempfile)
end
end)
it('dump', function()
eq(0, eval('v:profiling'))
command('profile start ' .. tempfile)
eq(1, eval('v:profiling'))
assert_file_exists_not(tempfile)
command('profile dump')
assert_file_exists(tempfile)
end)
it('stop', function()
command('profile start ' .. tempfile)
assert_file_exists_not(tempfile)
command('profile stop')
assert_file_exists(tempfile)
eq(0, eval('v:profiling'))
end)
end)