mirrors/neovim
1
0
Fork 0
mirror of https://github.com/neovim/neovim.git synced 2025-09-10 13:28:19 +00:00
Code Issues Packages Projects Releases Wiki Activity

profiling: implement on top of os_hrtime()

Browse Source 
Should be better than gettimeofday() since libuv uses higher resolution
clocks on most UNIX platforms. Libuv also tries to use monotonic clocks,
kernel bugs notwithstanding, which is another win over gettimeofday().

Necessary for Windows, which doesn't have gettimeofday(). In vanilla vim,
Windows uses QueryPerformanceCounter, which is the correct primitive for
this sort of things, but that was removed when slimming up the codebase.
Libuv uses QueryPerformanceCounter to implement uv_hrtime() on Windows so
the behaviour of vim profiling on Windows should now be the same.

The behaviour on Linux should be different (better) though, libuv uses more
accurate primitives than gettimeofday().

Other misc. changes:
- Added function attributes where relevant (const, pure, ...)
- Convert functions to receive scalars: Now that proftime_T is always a
  (uint64_t) scalar (and not a struct), it's clearer to convert the
  functions to receive it as such instead of a pointer to a scalar.
- Extract profiling funcs to profile.c: make everything clearer and reduces
  the size of the "catch-all" ex_cmds2.c
- Add profile.{c,h} to clint and -Wconv:
  - Don't use sprintf, use snprintf
  - Don't use long, use int16_t/int32_t/...
This commit is contained in:
Nicolas Hillegeer
2014-06-15 12:29:32 +02:00
parent f172b19f43
commit db7cd61f62
14 changed files with 387 additions and 316 deletions
Download Patch File Download Diff File Expand all files Collapse all files

2
clint-files.txt
View File

@@ -50,3 +50,5 @@ src/nvim/os/channel.c
src/nvim/os/channel.h
src/nvim/tempfile.c
src/nvim/tempfile.h
src/nvim/profile.c
src/nvim/profile.h

2
src/nvim/CMakeLists.txt
View File

@@ -45,6 +45,8 @@ set(CONV_SRCS
map.c
memory.c
misc2.c
map.c
profile.c
os/env.c
os/event.c
os/job.c

2
src/nvim/buffer_defs.h
View File

@@ -17,6 +17,8 @@
#include "nvim/hashtab.h"
// for dict_T
#include "nvim/eval_defs.h"
// for proftime_T
#include "nvim/profile.h"
/*
* Flags for w_valid.

203
src/nvim/eval.c
View File

@@ -18,6 +18,7 @@
#include <stdbool.h>
#include <math.h>
#include "nvim/assert.h"
#include "nvim/vim.h"
#include "nvim/ascii.h"
#ifdef HAVE_LOCALE_H
@@ -59,6 +60,7 @@
#include "nvim/os_unix.h"
#include "nvim/path.h"
#include "nvim/popupmnu.h"
#include "nvim/profile.h"
#include "nvim/quickfix.h"
#include "nvim/regexp.h"
#include "nvim/screen.h"
@@ -1209,8 +1211,10 @@ void prof_child_enter(proftime_T *tm /* place to store waittime */
{
funccall_T *fc = current_funccal;
if (fc != NULL && fc->func->uf_profiling)
profile_start(&fc->prof_child);
if (fc != NULL && fc->func->uf_profiling) {
fc->prof_child = profile_start();
}
script_prof_save(tm);
}
@@ -1224,10 +1228,13 @@ void prof_child_exit(proftime_T *tm /* where waittime was stored */
funccall_T *fc = current_funccal;
if (fc != NULL && fc->func->uf_profiling) {
profile_end(&fc->prof_child);
profile_sub_wait(tm, &fc->prof_child); /* don't count waiting time */
profile_add(&fc->func->uf_tm_children, &fc->prof_child);
profile_add(&fc->func->uf_tml_children, &fc->prof_child);
fc->prof_child = profile_end(fc->prof_child);
// don't count waiting time
fc->prof_child = profile_sub_wait(*tm, fc->prof_child);
fc->func->uf_tm_children =
profile_add(fc->func->uf_tm_children, fc->prof_child);
fc->func->uf_tml_children =
profile_add(fc->func->uf_tml_children, fc->prof_child);
}
script_prof_restore(tm);
}
@@ -11646,66 +11653,101 @@ static void f_readfile(typval_T *argvars, typval_T *rettv)
}
/*
* Convert a List to proftime_T.
* Return FAIL when there is something wrong.
*/
static int list2proftime(typval_T *arg, proftime_T *tm)
/// list2proftime - convert a List to proftime_T
///
/// @param arg The input list, must be of type VAR_LIST and have
/// exactly 2 items
/// @param[out] tm The proftime_T representation of `arg`
/// @return OK In case of success, FAIL in case of error
static int list2proftime(typval_T *arg, proftime_T *tm) FUNC_ATTR_NONNULL_ALL
{
long n1, n2;
int error = FALSE;
if (arg->v_type != VAR_LIST || arg->vval.v_list == NULL
|| arg->vval.v_list->lv_len != 2)
if (arg->v_type != VAR_LIST
|| arg->vval.v_list == NULL
|| arg->vval.v_list->lv_len != 2) {
return FAIL;
n1 = list_find_nr(arg->vval.v_list, 0L, &error);
n2 = list_find_nr(arg->vval.v_list, 1L, &error);
tm->tv_sec = n1;
tm->tv_usec = n2;
return error ? FAIL : OK;
}
/*
* "reltime()" function
*/
static void f_reltime(typval_T *argvars, typval_T *rettv)
int error = false;
varnumber_T n1 = list_find_nr(arg->vval.v_list, 0L, &error);
varnumber_T n2 = list_find_nr(arg->vval.v_list, 1L, &error);
if (error) {
return FAIL;
}
// in f_reltime() we split up the 64-bit proftime_T into two 32-bit
// values, now we combine them again.
union {
struct { varnumber_T low, high; } split;
proftime_T prof;
} u = { .split.high = n1, .split.low = n2 };
*tm = u.prof;
return OK;
}
/// f_reltime - return an item that represents a time value
///
/// @param[out] rettv Without an argument it returns the current time. With
/// one argument it returns the time passed since the argument.
/// With two arguments it returns the time passed between
/// the two arguments.
static void f_reltime(typval_T *argvars, typval_T *rettv) FUNC_ATTR_NONNULL_ALL
{
proftime_T res;
proftime_T start;
if (argvars[0].v_type == VAR_UNKNOWN) {
/* No arguments: get current time. */
profile_start(&res);
// no arguments: get current time.
res = profile_start();
} else if (argvars[1].v_type == VAR_UNKNOWN) {
if (list2proftime(&argvars[0], &res) == FAIL)
if (list2proftime(&argvars[0], &res) == FAIL) {
return;
profile_end(&res);
} else {
/* Two arguments: compute the difference. */
if (list2proftime(&argvars[0], &start) == FAIL
|| list2proftime(&argvars[1], &res) == FAIL)
return;
profile_sub(&res, &start);
}
res = profile_end(res);
} else {
// two arguments: compute the difference.
if (list2proftime(&argvars[0], &start) == FAIL
|| list2proftime(&argvars[1], &res) == FAIL) {
return;
}
res = profile_sub(res, start);
}
// we have to store the 64-bit proftime_T inside of a list of int's
// (varnumber_T is defined as int). For all our supported platforms, int's
// are at least 32-bits wide. So we'll use two 32-bit values to store it.
union {
struct { varnumber_T low, high; } split;
proftime_T prof;
} u = { .prof = res };
// statically assert that the union type conv will provide the correct
// results, if varnumber_T or proftime_T change, the union cast will need
// to be revised.
STATIC_ASSERT(sizeof(u.prof) == sizeof(u) && sizeof(u.split) == sizeof(u),
"type punning will produce incorrect results on this platform");
rettv_list_alloc(rettv);
long n1 = res.tv_sec;
long n2 = res.tv_usec;
list_append_number(rettv->vval.v_list, (varnumber_T)n1);
list_append_number(rettv->vval.v_list, (varnumber_T)n2);
list_append_number(rettv->vval.v_list, u.split.high);
list_append_number(rettv->vval.v_list, u.split.low);
}
/*
* "reltimestr()" function
*/
/// f_reltimestr - return a string that represents the value of {time}
///
/// @return The string representation of the argument, the format is the
/// number of seconds followed by a dot, followed by the number
/// of microseconds.
static void f_reltimestr(typval_T *argvars, typval_T *rettv)
FUNC_ATTR_NONNULL_ALL
{
proftime_T tm;
rettv->v_type = VAR_STRING;
rettv->vval.v_string = NULL;
if (list2proftime(&argvars[0], &tm) == OK)
rettv->vval.v_string = vim_strsave((char_u *)profile_msg(&tm));
if (list2proftime(&argvars[0], &tm) == OK) {
rettv->vval.v_string = (char_u *) xstrdup(profile_msg(tm));
}
}
/*
@@ -12134,7 +12176,7 @@ static int search_cmn(typval_T *argvars, pos_T *match_pos, int *flagsp)
}
/* Set the time limit, if there is one. */
profile_setlimit(time_limit, &tm);
tm = profile_setlimit(time_limit);
/*
* This function does not accept SP_REPEAT and SP_RETCOUNT flags.
@@ -12426,7 +12468,7 @@ do_searchpair (
p_cpo = empty_option;
/* Set the time limit, if there is one. */
profile_setlimit(time_limit, &tm);
tm = profile_setlimit(time_limit);
/* Make two search patterns: start/end (pat2, for in nested pairs) and
* start/middle/end (pat3, for the top pair). */
@@ -17435,8 +17477,8 @@ static void func_do_profile(ufunc_T *fp)
if (len == 0)
len = 1; /* avoid getting error for allocating zero bytes */
fp->uf_tm_count = 0;
profile_zero(&fp->uf_tm_self);
profile_zero(&fp->uf_tm_total);
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));
@@ -17488,8 +17530,8 @@ void func_dump_profile(FILE *fd)
fprintf(fd, "Called 1 time\n");
else
fprintf(fd, "Called %d times\n", fp->uf_tm_count);
fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total));
fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self));
fprintf(fd, "Total time: %s\n", profile_msg(fp->uf_tm_total));
fprintf(fd, " Self time: %s\n", profile_msg(fp->uf_tm_self));
fprintf(fd, "\n");
fprintf(fd, "count total (s) self (s)\n");
@@ -17556,14 +17598,14 @@ static void prof_func_line(
{
if (count > 0) {
fprintf(fd, "%5d ", count);
if (prefer_self && profile_equal(total, self))
if (prefer_self && profile_equal(*total, *self))
fprintf(fd, " ");
else
fprintf(fd, "%s ", profile_msg(total));
if (!prefer_self && profile_equal(total, self))
fprintf(fd, "%s ", profile_msg(*total));
if (!prefer_self && profile_equal(*total, *self))
fprintf(fd, " ");
else
fprintf(fd, "%s ", profile_msg(self));
fprintf(fd, "%s ", profile_msg(*self));
} else
fprintf(fd, " ");
}
@@ -17573,11 +17615,9 @@ static void prof_func_line(
*/
static int prof_total_cmp(const void *s1, const void *s2)
{
ufunc_T *p1, *p2;
p1 = *(ufunc_T **)s1;
p2 = *(ufunc_T **)s2;
return profile_cmp(&p1->uf_tm_total, &p2->uf_tm_total);
ufunc_T *p1 = *(ufunc_T **)s1;
ufunc_T *p2 = *(ufunc_T **)s2;
return profile_cmp(p1->uf_tm_total, p2->uf_tm_total);
}
/*
@@ -17585,11 +17625,9 @@ static int prof_total_cmp(const void *s1, const void *s2)
*/
static int prof_self_cmp(const void *s1, const void *s2)
{
ufunc_T *p1, *p2;
p1 = *(ufunc_T **)s1;
p2 = *(ufunc_T **)s2;
return profile_cmp(&p1->uf_tm_self, &p2->uf_tm_self);
ufunc_T *p1 = *(ufunc_T **)s1;
ufunc_T *p2 = *(ufunc_T **)s2;
return profile_cmp(p1->uf_tm_self, p2->uf_tm_self);
}
@@ -18018,8 +18056,8 @@ call_user_func (
if (fp->uf_profiling
|| (fc->caller != NULL && fc->caller->func->uf_profiling)) {
++fp->uf_tm_count;
profile_start(&call_start);
profile_zero(&fp->uf_tm_children);
call_start = profile_start();
fp->uf_tm_children = profile_zero();
}
script_prof_save(&wait_start);
}
@@ -18046,13 +18084,16 @@ call_user_func (
if (do_profiling == PROF_YES && (fp->uf_profiling
|| (fc->caller != NULL &&
fc->caller->func->uf_profiling))) {
profile_end(&call_start);
profile_sub_wait(&wait_start, &call_start);
profile_add(&fp->uf_tm_total, &call_start);
profile_self(&fp->uf_tm_self, &call_start, &fp->uf_tm_children);
call_start = profile_end(call_start);
call_start = profile_sub_wait(wait_start, call_start);
fp->uf_tm_total = profile_add(fp->uf_tm_total, call_start);
fp->uf_tm_self = profile_self(fp->uf_tm_self, call_start,
fp->uf_tm_children);
if (fc->caller != NULL && fc->caller->func->uf_profiling) {
profile_add(&fc->caller->func->uf_tm_children, &call_start);
profile_add(&fc->caller->func->uf_tml_children, &call_start);
fc->caller->func->uf_tm_children =
profile_add(fc->caller->func->uf_tm_children, call_start);
fc->caller->func->uf_tml_children =
profile_add(fc->caller->func->uf_tml_children, call_start);
}
}
@@ -18415,9 +18456,9 @@ void func_line_start(void *cookie)
while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL)
--fp->uf_tml_idx;
fp->uf_tml_execed = FALSE;
profile_start(&fp->uf_tml_start);
profile_zero(&fp->uf_tml_children);
profile_get_wait(&fp->uf_tml_wait);
fp->uf_tml_start = profile_start();
fp->uf_tml_children = profile_zero();
fp->uf_tml_wait = profile_get_wait();
}
}
@@ -18444,11 +18485,13 @@ void func_line_end(void *cookie)
if (fp->uf_profiling && fp->uf_tml_idx >= 0) {
if (fp->uf_tml_execed) {
++fp->uf_tml_count[fp->uf_tml_idx];
profile_end(&fp->uf_tml_start);
profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start);
profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start);
profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start,
&fp->uf_tml_children);
fp->uf_tml_start = profile_end(fp->uf_tml_start);
fp->uf_tml_start = profile_sub_wait(fp->uf_tml_wait, fp->uf_tml_start);
fp->uf_tml_total[fp->uf_tml_idx] =
profile_add(fp->uf_tml_total[fp->uf_tml_idx], fp->uf_tml_start);
fp->uf_tml_self[fp->uf_tml_idx] =
profile_self(fp->uf_tml_self[fp->uf_tml_idx], fp->uf_tml_start,
fp->uf_tml_children);
}
fp->uf_tml_idx = -1;
}

2
src/nvim/eval.h
View File

@@ -1,6 +1,8 @@
#ifndef NVIM_EVAL_H
#define NVIM_EVAL_H
#include "nvim/profile.h"
/* Defines for Vim variables. These must match vimvars[] in eval.c! */
enum {
VV_COUNT,

254
src/nvim/ex_cmds2.c
View File

@@ -50,6 +50,7 @@
#include "nvim/term.h"
#include "nvim/undo.h"
#include "nvim/window.h"
#include "nvim/profile.h"
#include "nvim/os/os.h"
#include "nvim/os/shell.h"
#include "nvim/os/fs_defs.h"
@@ -744,184 +745,6 @@ void dbg_breakpoint(char_u *name, linenr_T lnum)
debug_breakpoint_lnum = lnum;
}
/*
* Store the current time in "tm".
*/
void profile_start(proftime_T *tm)
{
gettimeofday(tm, NULL);
}
/*
* Compute the elapsed time from "tm" till now and store in "tm".
*/
void profile_end(proftime_T *tm)
{
proftime_T now;
gettimeofday(&now, NULL);
tm->tv_usec = now.tv_usec - tm->tv_usec;
tm->tv_sec = now.tv_sec - tm->tv_sec;
if (tm->tv_usec < 0) {
tm->tv_usec += 1000000;
--tm->tv_sec;
}
}
/*
* Subtract the time "tm2" from "tm".
*/
void profile_sub(proftime_T *tm, proftime_T *tm2)
{
tm->tv_usec -= tm2->tv_usec;
tm->tv_sec -= tm2->tv_sec;
if (tm->tv_usec < 0) {
tm->tv_usec += 1000000;
--tm->tv_sec;
}
}
/*
* Return a string that represents the time in "tm".
* Uses a static buffer!
*/
char * profile_msg(proftime_T *tm)
{
static char buf[50];
sprintf(buf, "%3ld.%06ld", (long)tm->tv_sec, (long)tm->tv_usec);
return buf;
}
/*
* Put the time "msec" past now in "tm".
*/
void profile_setlimit(long msec, proftime_T *tm)
{
if (msec <= 0) /* no limit */
profile_zero(tm);
else {
long usec;
gettimeofday(tm, NULL);
usec = (long)tm->tv_usec + (long)msec * 1000;
tm->tv_usec = usec % 1000000L;
tm->tv_sec += usec / 1000000L;
}
}
/*
* Return TRUE if the current time is past "tm".
*/
int profile_passed_limit(proftime_T *tm)
{
proftime_T now;
if (tm->tv_sec == 0) /* timer was not set */
return FALSE;
gettimeofday(&now, NULL);
return now.tv_sec > tm->tv_sec
|| (now.tv_sec == tm->tv_sec && now.tv_usec > tm->tv_usec);
}
/*
* Set the time in "tm" to zero.
*/
void profile_zero(proftime_T *tm)
{
tm->tv_usec = 0;
tm->tv_sec = 0;
}
#include <math.h>
/*
* Divide the time "tm" by "count" and store in "tm2".
*/
void profile_divide(proftime_T *tm, int count, proftime_T *tm2)
{
if (count == 0)
profile_zero(tm2);
else {
double usec = (tm->tv_sec * 1000000.0 + tm->tv_usec) / count;
tm2->tv_sec = floor(usec / 1000000.0);
tm2->tv_usec = round(usec - (tm2->tv_sec * 1000000.0));
}
}
/*
* Functions for profiling.
*/
static proftime_T prof_wait_time;
/*
* Add the time "tm2" to "tm".
*/
void profile_add(proftime_T *tm, proftime_T *tm2)
{
tm->tv_usec += tm2->tv_usec;
tm->tv_sec += tm2->tv_sec;
if (tm->tv_usec >= 1000000) {
tm->tv_usec -= 1000000;
++tm->tv_sec;
}
}
/*
* Add the "self" time from the total time and the children's time.
*/
void profile_self(proftime_T *self, proftime_T *total, proftime_T *children)
{
/* Check that the result won't be negative. Can happen with recursive
* calls. */
if (total->tv_sec < children->tv_sec
|| (total->tv_sec == children->tv_sec
&& total->tv_usec <= children->tv_usec))
return;
profile_add(self, total);
profile_sub(self, children);
}
/*
* Get the current waittime.
*/
void profile_get_wait(proftime_T *tm)
{
*tm = prof_wait_time;
}
/*
* Subtract the passed waittime since "tm" from "tma".
*/
void profile_sub_wait(proftime_T *tm, proftime_T *tma)
{
proftime_T tm3 = prof_wait_time;
profile_sub(&tm3, tm);
profile_sub(tma, &tm3);
}
/*
* Return TRUE if "tm1" and "tm2" are equal.
*/
int profile_equal(proftime_T *tm1, proftime_T *tm2)
{
return tm1->tv_usec == tm2->tv_usec && tm1->tv_sec == tm2->tv_sec;
}
/*
* Return <0, 0 or >0 if "tm1" < "tm2", "tm1" == "tm2" or "tm1" > "tm2"
*/
int profile_cmp(const proftime_T *tm1, const proftime_T *tm2)
{
if (tm1->tv_sec == tm2->tv_sec)
return tm2->tv_usec - tm1->tv_usec;
return tm2->tv_sec - tm1->tv_sec;
}
static char_u *profile_fname = NULL;
static proftime_T pause_time;
@@ -941,18 +764,18 @@ void ex_profile(exarg_T *eap)
free(profile_fname);
profile_fname = vim_strsave(e);
do_profiling = PROF_YES;
profile_zero(&prof_wait_time);
profile_set_wait(profile_zero());
set_vim_var_nr(VV_PROFILING, 1L);
} else if (do_profiling == PROF_NONE)
EMSG(_("E750: First use \":profile start {fname}\""));
else if (STRCMP(eap->arg, "pause") == 0) {
if (do_profiling == PROF_YES)
profile_start(&pause_time);
pause_time = profile_start();
do_profiling = PROF_PAUSED;
} else if (STRCMP(eap->arg, "continue") == 0) {
if (do_profiling == PROF_PAUSED) {
profile_end(&pause_time);
profile_add(&prof_wait_time, &pause_time);
pause_time = profile_end(pause_time);
profile_set_wait(profile_add(profile_get_wait(), pause_time));
}
do_profiling = PROF_YES;
} else {
@@ -1048,8 +871,8 @@ void profile_dump(void)
static void script_do_profile(scriptitem_T *si)
{
si->sn_pr_count = 0;
profile_zero(&si->sn_pr_total);
profile_zero(&si->sn_pr_self);
si->sn_pr_total = profile_zero();
si->sn_pr_self = profile_zero();
ga_init(&si->sn_prl_ga, sizeof(sn_prl_T), 100);
si->sn_prl_idx = -1;
@@ -1069,9 +892,9 @@ void script_prof_save(
if (current_SID > 0 && current_SID <= script_items.ga_len) {
si = &SCRIPT_ITEM(current_SID);
if (si->sn_prof_on && si->sn_pr_nest++ == 0)
profile_start(&si->sn_pr_child);
si->sn_pr_child = profile_start();
}
profile_get_wait(tm);
*tm = profile_get_wait();
}
/*
@@ -1084,10 +907,11 @@ void script_prof_restore(proftime_T *tm)
if (current_SID > 0 && current_SID <= script_items.ga_len) {
si = &SCRIPT_ITEM(current_SID);
if (si->sn_prof_on && --si->sn_pr_nest == 0) {
profile_end(&si->sn_pr_child);
profile_sub_wait(tm, &si->sn_pr_child); /* don't count wait time */
profile_add(&si->sn_pr_children, &si->sn_pr_child);
profile_add(&si->sn_prl_children, &si->sn_pr_child);
si->sn_pr_child = profile_end(si->sn_pr_child);
// don't count wait time
si->sn_pr_child = profile_sub_wait(*tm, si->sn_pr_child);
si->sn_pr_children = profile_add(si->sn_pr_children, si->sn_pr_child);
si->sn_prl_children = profile_add(si->sn_prl_children, si->sn_pr_child);
}
}
}
@@ -1099,7 +923,7 @@ static proftime_T inchar_time;
*/
void prof_inchar_enter(void)
{
profile_start(&inchar_time);
inchar_time = profile_start();
}
/*
@@ -1107,8 +931,8 @@ void prof_inchar_enter(void)
*/
void prof_inchar_exit(void)
{
profile_end(&inchar_time);
profile_add(&prof_wait_time, &inchar_time);
inchar_time = profile_end(inchar_time);
profile_set_wait(profile_add(profile_get_wait(), inchar_time));
}
/*
@@ -1128,8 +952,8 @@ static void script_dump_profile(FILE *fd)
fprintf(fd, "Sourced 1 time\n");
else
fprintf(fd, "Sourced %d times\n", si->sn_pr_count);
fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total));
fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self));
fprintf(fd, "Total time: %s\n", profile_msg(si->sn_pr_total));
fprintf(fd, " Self time: %s\n", profile_msg(si->sn_pr_self));
fprintf(fd, "\n");
fprintf(fd, "count total (s) self (s)\n");
@@ -1143,11 +967,11 @@ static void script_dump_profile(FILE *fd)
pp = &PRL_ITEM(si, i);
if (pp->snp_count > 0) {
fprintf(fd, "%5d ", pp->snp_count);
if (profile_equal(&pp->sn_prl_total, &pp->sn_prl_self))
if (profile_equal(pp->sn_prl_total, pp->sn_prl_self))
fprintf(fd, " ");
else
fprintf(fd, "%s ", profile_msg(&pp->sn_prl_total));
fprintf(fd, "%s ", profile_msg(&pp->sn_prl_self));
fprintf(fd, "%s ", profile_msg(pp->sn_prl_total));
fprintf(fd, "%s ", profile_msg(pp->sn_prl_self));
} else
fprintf(fd, " ");
fprintf(fd, "%s", IObuff);
@@ -2610,8 +2434,8 @@ do_source (
}
if (si->sn_prof_on) {
++si->sn_pr_count;
profile_start(&si->sn_pr_start);
profile_zero(&si->sn_pr_children);
si->sn_pr_start = profile_start();
si->sn_pr_children = profile_zero();
}
}
@@ -2626,11 +2450,11 @@ do_source (
/* Get "si" again, "script_items" may have been reallocated. */
si = &SCRIPT_ITEM(current_SID);
if (si->sn_prof_on) {
profile_end(&si->sn_pr_start);
profile_sub_wait(&wait_start, &si->sn_pr_start);
profile_add(&si->sn_pr_total, &si->sn_pr_start);
profile_self(&si->sn_pr_self, &si->sn_pr_start,
&si->sn_pr_children);
si->sn_pr_start = profile_end(si->sn_pr_start);
si->sn_pr_start = profile_sub_wait(wait_start, si->sn_pr_start);
si->sn_pr_total = profile_add(si->sn_pr_total, si->sn_pr_start);
si->sn_pr_self = profile_self(si->sn_pr_self, si->sn_pr_start,
si->sn_pr_children);
}
}
@@ -2949,14 +2773,14 @@ void script_line_start(void)
/* Zero counters for a line that was not used before. */
pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len);
pp->snp_count = 0;
profile_zero(&pp->sn_prl_total);
profile_zero(&pp->sn_prl_self);
pp->sn_prl_total = profile_zero();
pp->sn_prl_self = profile_zero();
++si->sn_prl_ga.ga_len;
}
si->sn_prl_execed = FALSE;
profile_start(&si->sn_prl_start);
profile_zero(&si->sn_prl_children);
profile_get_wait(&si->sn_prl_wait);
si->sn_prl_start = profile_start();
si->sn_prl_children = profile_zero();
si->sn_prl_wait = profile_get_wait();
}
}
@@ -2990,11 +2814,11 @@ void script_line_end(void)
if (si->sn_prl_execed) {
pp = &PRL_ITEM(si, si->sn_prl_idx);
++pp->snp_count;
profile_end(&si->sn_prl_start);
profile_sub_wait(&si->sn_prl_wait, &si->sn_prl_start);
profile_add(&pp->sn_prl_total, &si->sn_prl_start);
profile_self(&pp->sn_prl_self, &si->sn_prl_start,
&si->sn_prl_children);
si->sn_prl_start = profile_end(si->sn_prl_start);
si->sn_prl_start = profile_sub_wait(si->sn_prl_wait, si->sn_prl_start);
pp->sn_prl_total = profile_add(pp->sn_prl_total, si->sn_prl_start);
pp->sn_prl_self = profile_self(pp->sn_prl_self, si->sn_prl_start,
si->sn_prl_children);
}
si->sn_prl_idx = -1;
}

2
src/nvim/ex_getln.c
View File

@@ -1396,7 +1396,7 @@ cmdline_changed:
out_flush();
++emsg_off; /* So it doesn't beep if bad expr */
/* Set the time limit to half a second. */
profile_setlimit(500L, &tm);
tm = profile_setlimit(500L);
i = do_search(NULL, firstc, ccline.cmdbuff, count,
SEARCH_KEEP + SEARCH_OPT + SEARCH_NOOF + SEARCH_PEEK,
&tm

184
src/nvim/profile.c Normal file
View File

@@ -0,0 +1,184 @@
#include <stdio.h>
#include <math.h>
#include <assert.h>
#include "nvim/profile.h"
#include "nvim/os/time.h"
#include "nvim/func_attr.h"
#ifdef INCLUDE_GENERATED_DECLARATIONS
# include "profile.c.generated.h"
#endif
/// functions for profiling
static proftime_T prof_wait_time;
/// profile_start - return the current time
///
/// @return the current time
proftime_T profile_start(void) FUNC_ATTR_WARN_UNUSED_RESULT
{
return os_hrtime();
}
/// profile_end - compute the time elapsed
///
/// @return the elapsed time from `tm` until now.
proftime_T profile_end(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT
{
return os_hrtime() - tm;
}
/// profile_msg - return a string that represents the time in `tm`
///
/// @warning Do not modify or free this string, not multithread-safe.
///
/// @param tm The time to be represented
/// @return a static string representing `tm` in the
/// form "seconds.microseconds".
const char *profile_msg(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT
{
static char buf[50];
snprintf(buf, sizeof(buf), "%10.6lf", (double)tm / 1000000000.0);
return buf;
}
/// profile_setlimit - return the time `msec` into the future
///
/// @param msec milliseconds, the maximum number of milliseconds is
/// (2^63 / 10^6) - 1 = 9.223372e+12.
/// @return if msec > 0, returns the time msec past now. Otherwise returns
/// the zero time.
proftime_T profile_setlimit(int64_t msec) FUNC_ATTR_WARN_UNUSED_RESULT
{
if (msec <= 0) {
// no limit
return profile_zero();
}
assert(msec <= (INT64_MAX / 1000000LL) - 1);
proftime_T nsec = (proftime_T) msec * 1000000ULL;
return os_hrtime() + nsec;
}
/// profile_passed_limit - check if current time has passed `tm`
///
/// @return true if the current time is past `tm`, false if not or if the
/// timer was not set.
bool profile_passed_limit(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT
{
if (tm == 0) {
// timer was not set
return false;
}
return profile_cmp(os_hrtime(), tm) < 0;
}
/// profile_zero - obtain the zero time
///
/// @return the zero time
proftime_T profile_zero(void) FUNC_ATTR_CONST
{
return 0;
}
/// profile_divide - divide the time `tm` by `count`.
///
/// @return 0 if count <= 0, otherwise tm / count
proftime_T profile_divide(proftime_T tm, int count) FUNC_ATTR_CONST
{
if (count <= 0) {
return profile_zero();
}
return (proftime_T) round((double) tm / (double) count);
}
/// profile_add - add the time `tm2` to `tm1`
///
/// @return `tm1` + `tm2`
proftime_T profile_add(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST
{
return tm1 + tm2;
}
/// profile_sub - subtract `tm2` from `tm1`
///
/// @return `tm1` - `tm2`
proftime_T profile_sub(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST
{
return tm1 - tm2;
}
/// profile_self - add the `self` time from the total time and the
/// children's time
///
/// @return if `total` <= `children`, then self, otherwise `self` + `total` -
/// `children`
proftime_T profile_self(proftime_T self, proftime_T total, proftime_T children)
FUNC_ATTR_CONST
{
// check that the result won't be negative, which can happen with
// recursive calls.
if (total <= children) {
return self;
}
// add the total time to self and subtract the children's time from self
return profile_sub(profile_add(self, total), children);
}
/// profile_get_wait - get the current waittime
///
/// @return the current waittime
proftime_T profile_get_wait(void) FUNC_ATTR_PURE
{
return prof_wait_time;
}
/// profile_set_wait - set the current waittime
void profile_set_wait(proftime_T wait)
{
prof_wait_time = wait;
}
/// profile_sub_wait - subtract the passed waittime since `tm`
///
/// @return `tma` - (waittime - `tm`)
proftime_T profile_sub_wait(proftime_T tm, proftime_T tma) FUNC_ATTR_PURE
{
proftime_T tm3 = profile_sub(profile_get_wait(), tm);
return profile_sub(tma, tm3);
}
/// profile_equal - check if `tm1` is equal to `tm2`
///
/// @return true if `tm1` == `tm2`
bool profile_equal(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST
{
return tm1 == tm2;
}
/// sgn64 - calculates the sign of a 64-bit integer
///
/// @return -1, 0, or +1
static inline int sgn64(int64_t x) FUNC_ATTR_CONST
{
return (int) ((x > 0) - (x < 0));
}
/// profile_cmp - compare profiling times
///
/// Only guarantees correct results if both input times are not more than
/// 150 years apart.
///
/// @return <0, 0 or >0 if `tm2` < `tm1`, `tm2` == `tm1` or `tm2` > `tm1`
int profile_cmp(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST
{
return sgn64((int64_t)(tm2 - tm1));
}

13
src/nvim/profile.h Normal file
View File

@@ -0,0 +1,13 @@
#ifndef NVIM_PROFILE_H
#define NVIM_PROFILE_H
#include <stdint.h>
#include <time.h>
typedef uint64_t proftime_T;
#ifdef INCLUDE_GENERATED_DECLARATIONS
# include "profile.h.generated.h"
#endif
#endif // NVIM_PROFILE_H

2
src/nvim/regexp.c
View File

@@ -3468,7 +3468,7 @@ static long bt_regexec_both(char_u *line,
/* Check for timeout once in a twenty times to avoid overhead. */
if (tm != NULL && ++tm_count == 20) {
tm_count = 0;
if (profile_passed_limit(tm))
if (profile_passed_limit(*tm))
break;
}
}

6
src/nvim/screen.c
View File

@@ -5441,7 +5441,7 @@ static void start_search_hl(void)
last_pat_prog(&search_hl.rm);
search_hl.attr = hl_attr(HLF_L);
/* Set the time limit to 'redrawtime'. */
profile_setlimit(p_rdt, &search_hl.tm);
search_hl.tm = profile_setlimit(p_rdt);
}
}
@@ -5476,7 +5476,7 @@ static void init_search_hl(win_T *wp)
cur->hl.lnum = 0;
cur->hl.first_lnum = 0;
/* Set the time limit to 'redrawtime'. */
profile_setlimit(p_rdt, &(cur->hl.tm));
cur->hl.tm = profile_setlimit(p_rdt);
cur = cur->next;
}
search_hl.buf = wp->w_buffer;
@@ -5578,7 +5578,7 @@ next_search_hl (
called_emsg = FALSE;
for (;; ) {
/* Stop searching after passing the time limit. */
if (profile_passed_limit(&(shl->tm))) {
if (profile_passed_limit(shl->tm)) {
shl->lnum = 0; /* no match found in time */
break;
}

2
src/nvim/search.c
View File

@@ -530,7 +530,7 @@ int searchit(
? lnum > stop_lnum : lnum < stop_lnum))
break;
/* Stop after passing the "tm" time limit. */
if (tm != NULL && profile_passed_limit(tm))
if (tm != NULL && profile_passed_limit(*tm))
break;
/*

33
src/nvim/syntax.c
View File

@@ -2856,17 +2856,19 @@ static int syn_regexec(regmmatch_T *rmp, linenr_T lnum, colnr_T col, syn_time_T
int r;
proftime_T pt;
if (syn_time_on)
profile_start(&pt);
if (syn_time_on) {
pt = profile_start();
}
rmp->rmm_maxcol = syn_buf->b_p_smc;
r = vim_regexec_multi(rmp, syn_win, syn_buf, lnum, col, NULL);
if (syn_time_on) {
profile_end(&pt);
profile_add(&st->total, &pt);
if (profile_cmp(&pt, &st->slowest) < 0)
pt = profile_end(pt);
st->total = profile_add(st->total, pt);
if (profile_cmp(pt, st->slowest) < 0) {
st->slowest = pt;
}
++st->count;
if (r > 0)
++st->match;
@@ -5630,8 +5632,8 @@ void ex_syntime(exarg_T *eap)
static void syn_clear_time(syn_time_T *st)
{
profile_zero(&st->total);
profile_zero(&st->slowest);
st->total = profile_zero();
st->slowest = profile_zero();
st->count = 0;
st->match = 0;
}
@@ -5673,7 +5675,7 @@ static int syn_compare_syntime(const void *v1, const void *v2)
const time_entry_T *s1 = v1;
const time_entry_T *s2 = v2;
return profile_cmp(&s1->total, &s2->total);
return profile_cmp(s1->total, s2->total);
}
/*
@@ -5684,7 +5686,6 @@ static void syntime_report(void)
synpat_T *spp;
proftime_T tm;
int len;
proftime_T total_total;
int total_count = 0;
garray_T ga;
time_entry_T *p;
@@ -5695,18 +5696,18 @@ static void syntime_report(void)
}
ga_init(&ga, sizeof(time_entry_T), 50);
profile_zero(&total_total);
proftime_T total_total = profile_zero();
for (int idx = 0; idx < curwin->w_s->b_syn_patterns.ga_len; ++idx) {
spp = &(SYN_ITEMS(curwin->w_s)[idx]);
if (spp->sp_time.count > 0) {
p = GA_APPEND_VIA_PTR(time_entry_T, &ga);
p->total = spp->sp_time.total;
profile_add(&total_total, &spp->sp_time.total);
total_total = profile_add(total_total, spp->sp_time.total);
p->count = spp->sp_time.count;
p->match = spp->sp_time.match;
total_count += spp->sp_time.count;
p->slowest = spp->sp_time.slowest;
profile_divide(&spp->sp_time.total, spp->sp_time.count, &tm);
tm = profile_divide(spp->sp_time.total, spp->sp_time.count);
p->average = tm;
p->id = spp->sp_syn.id;
p->pattern = spp->sp_pattern;
@@ -5724,7 +5725,7 @@ static void syntime_report(void)
spp = &(SYN_ITEMS(curwin->w_s)[idx]);
p = ((time_entry_T *)ga.ga_data) + idx;
MSG_PUTS(profile_msg(&p->total));
MSG_PUTS(profile_msg(p->total));
MSG_PUTS(" "); /* make sure there is always a separating space */
msg_advance(13);
msg_outnum(p->count);
@@ -5733,10 +5734,10 @@ static void syntime_report(void)
msg_outnum(p->match);
MSG_PUTS(" ");
msg_advance(26);
MSG_PUTS(profile_msg(&p->slowest));
MSG_PUTS(profile_msg(p->slowest));
MSG_PUTS(" ");
msg_advance(38);
MSG_PUTS(profile_msg(&p->average));
MSG_PUTS(profile_msg(p->average));
MSG_PUTS(" ");
msg_advance(50);
msg_outtrans(HL_TABLE()[p->id - 1].sg_name);
@@ -5755,7 +5756,7 @@ static void syntime_report(void)
ga_clear(&ga);
if (!got_int) {
MSG_PUTS("\n");
MSG_PUTS(profile_msg(&total_total));
MSG_PUTS(profile_msg(total_total));
msg_advance(13);
msg_outnum(total_count);
MSG_PUTS("\n");

2
src/nvim/vim.h
View File

@@ -426,8 +426,6 @@ typedef void *vim_acl_T; /* dummy to pass an ACL to a function */
* plus six following composing characters of three bytes each. */
# define MB_MAXBYTES 21
typedef struct timeval proftime_T;