kevin/neovim
1
Fork 0
mirror of https://github.com/neovim/neovim.git synced 2024-12-23 20:55:18 -07:00
Code Issues Packages Projects Releases Wiki Activity

Merge pull request #839 from aktau/platform-abstract-time-fn

Browse Source 
viml: impl profiling on top of uv_hrtime()
This commit is contained in:
Justin M. Keyes 2014-07-16 12:46:07 -04:00
commit 0412c17a65
17 changed files with 722 additions and 317 deletions
Show Stats 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

78
src/nvim/assert.h Normal file
View File

@ -0,0 +1,78 @@
#ifndef NVIM_ASSERT_H
#define NVIM_ASSERT_H
// support static asserts (aka compile-time asserts)
// some compilers don't properly support short-circuiting apparently, giving
// ugly syntax errors when using things like defined(__clang__) &&
// defined(__has_feature) && __has_feature(...). Therefore we define Clang's
// __has_feature and __has_extension macro's before referring to them.
#ifndef __has_feature
#define __has_feature(x) 0
#endif
#ifndef __has_extension
#define __has_extension __has_feature
#endif
/// STATIC_ASSERT(condition, message) - assert at compile time if !cond
///
/// example:
/// STATIC_ASSERT(sizeof(void *) == 8, "need 64-bits mode");
// define STATIC_ASSERT as C11's _Static_assert whenever either C11 mode is
// detected or the compiler is known to support it. Note that Clang in C99
// mode defines __has_feature(c_static_assert) as false and
// __has_extension(c_static_assert) as true. Meaning it does support it, but
// warns. A similar thing goes for gcc, which warns when it's not compiling
// as C11 but does support _Static_assert since 4.6. Since we prefer the
// clearer messages we get from _Static_assert, we suppress the warnings
// temporarily.
// the easiest case, when the mode is C11 (generic compiler) or Clang
// advertises explicit support for c_static_assert, meaning it won't warn.
#if __STDC_VERSION__ >= 201112L || __has_feature(c_static_assert)
#define STATIC_ASSERT(cond, msg) _Static_assert(cond, msg)
// if we're dealing with gcc >= 4.6 in C99 mode, we can still use
// _Static_assert but we need to suppress warnings, this is pretty ugly.
#elif (!defined(__clang__) && !defined(__INTEL_COMPILER)) && \
(__GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ >= 6))
#define STATIC_ASSERT(cond, msg) \
_Pragma("GCC diagnostic push") \
_Pragma("GCC diagnostic ignored \"-pedantic\"") \
_Static_assert(cond, msg); \
_Pragma("GCC diagnostic pop") \
// the same goes for clang in C99 mode, but we suppress a different warning
#elif defined(__clang__) && __has_extension(c_static_assert)
#define STATIC_ASSERT(cond, msg) \
_Pragma("clang diagnostic push") \
_Pragma("clang diagnostic ignored \"-Wc11-extensions\"") \
_Static_assert(cond, msg); \
_Pragma("clang diagnostic pop") \
// TODO(aktau): verify that this works, don't have MSVC on hand.
#elif _MSC_VER >= 1600
#define STATIC_ASSERT(cond, msg) static_assert(cond, msg)
// fallback for compilers that don't support _Static_assert or static_assert
// not as pretty but gets the job done. Credit goes to Pádraig Brady and
// contributors.
#else
#define ASSERT_CONCAT_(a, b) a##b
#define ASSERT_CONCAT(a, b) ASSERT_CONCAT_(a, b)
// These can't be used after statements in c89.
#ifdef __COUNTER__
#define STATIC_ASSERT(e,m) \
{ enum { ASSERT_CONCAT(static_assert_, __COUNTER__) = 1/(!!(e)) }; }
#else
// This can't be used twice on the same line so ensure if using in headers
// that the headers are not included twice (by wrapping in #ifndef...#endif)
// Note it doesn't cause an issue when used on same line of separate modules
// compiled with gcc -combine -fwhole-program.
#define STATIC_ASSERT(e,m) \
{ enum { ASSERT_CONCAT(assert_line_, __LINE__) = 1/(!!(e)) }; }
#endif
#endif
#endif // NVIM_ASSERT_H

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.

197
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;
}
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;
}
/*
* "reltime()" function
*/
static void f_reltime(typval_T *argvars, typval_T *rettv)
/// 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);
}
res = profile_end(res);
} else {
/* Two arguments: compute the difference. */
// two arguments: compute the difference.
if (list2proftime(&argvars[0], &start) == FAIL
|| list2proftime(&argvars[1], &res) == FAIL)
|| list2proftime(&argvars[1], &res) == FAIL) {
return;
profile_sub(&res, &start);
}
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,

257
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,192 +745,15 @@ 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;
/*
* ":profile cmd args"
*/
void ex_profile(exarg_T *eap)
{
static proftime_T pause_time;
char_u *e;
int len;
@ -941,18 +765,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 +872,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 +893,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 +908,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 +924,7 @@ static proftime_T inchar_time;
*/
void prof_inchar_enter(void)
{
profile_start(&inchar_time);
inchar_time = profile_start();
}
/*
@ -1107,8 +932,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 +953,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 +968,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 +2435,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 +2451,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 +2774,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 +2815,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

9
src/nvim/os/time.c
View File

@ -22,6 +22,15 @@ void time_init(void)
uv_cond_init(&delay_cond);
}
/// Obtain a high-resolution timer value
///
/// @return a timer value, not related to the time of day and not subject
/// to clock drift. The value is expressed in nanoseconds.
uint64_t os_hrtime(void)
{
return uv_hrtime();
}
/// Sleeps for a certain amount of milliseconds
///
/// @param milliseconds Number of milliseconds to sleep

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;

246
test/unit/profile_spec.lua Normal file
View File

@ -0,0 +1,246 @@
local helpers = require 'test.unit.helpers'
local prof = helpers.cimport './src/nvim/profile.h'
local ffi = helpers.ffi
local eq = helpers.eq
local neq = helpers.neq
local function split(inputstr, sep)
if sep == nil then
sep = "%s"
end
local t, i = {}, 1
for str in string.gmatch(inputstr, "([^"..sep.."]+)") do
t[i] = str
i = i + 1
end
return t
end
local function trim(s)
local from = s:match"^%s*()"
return from > #s and "" or s:match(".*%S", from)
end
local function starts(str, start)
return string.sub(str, 1, string.len(start)) == start
end
local function cmp_assert(v1, v2, op, opstr)
local res = op(v1, v2)
if res == false then
print(string.format("expected: %f %s %f", v1, opstr, v2))
end
assert.is_true(res)
end
local function lt(v1, v2)
cmp_assert(v1, v2, function(v1, v2) return v1 < v2 end, "<")
end
local function lte(v1, v2)
cmp_assert(v1, v2, function(v1, v2) return v1 <= v2 end, "<=")
end
local function gt(v1, v2)
cmp_assert(v1, v2, function(v1, v2) return v1 > v2 end, ">")
end
local function gte(v1, v2)
cmp_assert(v1, v2, function(v1, v2) return v1 >= v2 end, ">=")
end
-- missing functions:
-- profile_self
-- profile_get_wait
-- profile_set_wait
-- profile_sub_wait
describe('profiling related functions', function()
local function profile_start() return prof.profile_start() end
local function profile_end(t) return prof.profile_end(t) end
local function profile_zero() return prof.profile_zero() end
local function profile_setlimit(ms) return prof.profile_setlimit(ms) end
local function profile_passed_limit(t) return prof.profile_passed_limit(t) end
local function profile_add(t1, t2) return prof.profile_add(t1, t2) end
local function profile_sub(t1, t2) return prof.profile_sub(t1, t2) end
local function profile_divide(t, cnt) return prof.profile_divide(t, cnt) end
local function profile_cmp(t1, t2) return prof.profile_cmp(t1, t2) end
local function profile_equal(t1, t2) return prof.profile_equal(t1, t2) end
local function profile_msg(t) return ffi.string(prof.profile_msg(t)) end
local function toseconds(t)
local str = trim(profile_msg(t))
local spl = split(str, ".")
local s, us = spl[1], spl[2]
return tonumber(s) + tonumber(us) / 1000000
end
describe('profile_equal', function()
it('times are equal to themselves', function()
local start = profile_start()
assert.is_true(profile_equal(start, start))
local e = profile_end(start)
assert.is_true(profile_equal(e, e))
end)
it('times are unequal to others', function()
assert.is_false(profile_equal(profile_start(), profile_start()))
end)
end)
-- this is quite difficult to test, as it would rely on other functions in
-- the profiling package. Those functions in turn will probably be tested
-- using profile_cmp... circular reasoning.
describe('profile_cmp', function()
it('can compare subsequent starts', function()
local s1, s2 = profile_start(), profile_start()
assert.is_true(profile_cmp(s1, s2) > 0)
assert.is_true(profile_cmp(s2, s1) < 0)
end)
it('can compare the zero element', function()
assert.is_true(profile_cmp(profile_zero(), profile_zero()) == 0)
end)
it('correctly orders divisions', function()
local start = profile_start()
assert.is_true(profile_cmp(start, profile_divide(start, 10)) <= 0)
end)
end)
describe('profile_divide', function()
it('actually performs division', function()
-- note: the routine actually performs floating-point division to get
-- better rounding behaviour, we have to take that into account when
-- checking. (check range, not exact number).
local divisor = 10
local start = profile_start()
local divided = profile_divide(start, divisor)
local res = divided
for i = 1, divisor - 1 do
res = profile_add(res, divided)
end
-- res should be in the range [start - divisor, start + divisor]
local start_min, start_max = profile_sub(start, divisor), profile_add(start, divisor)
assert.is_true(profile_cmp(start_min, res) >= 0)
assert.is_true(profile_cmp(start_max, res) <= 0)
end)
end)
describe('profile_zero', function()
it('returns the same value on each call', function()
eq(0, profile_zero())
assert.is_true(profile_equal(profile_zero(), profile_zero()))
end)
end)
describe('profile_start', function()
it('increases', function()
local last = profile_start()
for i=1,100 do
local curr = profile_start()
gte(curr, last)
last = curr
end
end)
end)
describe('profile_end', function()
it('the elapsed time cannot be zero', function()
neq(profile_zero(), profile_end(profile_start()))
end)
it('outer elapsed >= inner elapsed', function()
for i = 1, 100 do
local start_outer = profile_start()
local start_inner = profile_start()
local elapsed_inner = profile_end(start_inner)
local elapsed_outer = profile_end(start_outer)
gte(elapsed_outer, elapsed_inner)
end
end)
end)
describe('profile_setlimit', function()
it('sets no limit when 0 is passed', function()
eq(true, profile_equal(profile_setlimit(0), profile_zero()))
end)
it('sets a limit in the future otherwise', function()
local future = profile_setlimit(1000)
local now = profile_start()
assert.is_true(profile_cmp(future, now) < 0)
end)
end)
describe('profile_passed_limit', function()
it('start is in the past', function()
local start = profile_start()
eq(true, profile_passed_limit(start))
end)
it('start + start is in the future', function()
local start = profile_start()
local future = profile_add(start, start)
eq(false, profile_passed_limit(future))
end)
end)
describe('profile_msg', function()
it('prints the zero time as 0.00000', function()
local str = trim(profile_msg(profile_zero()))
eq(str, "0.000000")
end)
it('prints the time passed, in seconds.microsends', function()
local start = profile_start()
local endt = profile_end(start)
local str = trim(profile_msg(endt))
local spl = split(str, ".")
-- string has two parts (before dot and after dot)
eq(2, #spl)
local s, us = spl[1], spl[2]
-- zero seconds have passed (if this is not true, either LuaJIT is too
-- slow or the profiling functions are too slow and need to be fixed)
eq(s, "0")
-- more or less the same goes for the microsecond part, if it doesn't
-- start with 0, it's too slow.
assert.is_true(starts(us, "0"))
end)
end)
describe('profile_add', function()
it('adds profiling times', function()
local start = profile_start()
assert.equals(start, profile_add(profile_zero(), start))
end)
end)
describe('profile_sub', function()
it('subtracts profiling times', function()
-- subtracting zero does nothing
local start = profile_start()
assert.equals(start, profile_sub(start, profile_zero()))
local start1, start2, start3 = profile_start(), profile_start(), profile_start()
local cmp = profile_cmp(profile_sub(start2, start1), profile_sub(start3, start1))
-- t2 >= t1 => profile_cmp(t1, t2) >= 0
assert.is_true(cmp >= 0)
local cmp = profile_cmp(profile_sub(start3, start1), profile_sub(start2, start1))
-- t2 <= t1 => profile_cmp(t1, t2) <= 0
assert.is_true(cmp <= 0)
end)
end)
end)