From e2ce5ff9d6168de0ffaf59d6bf20f20631a34a2d Mon Sep 17 00:00:00 2001 From: "Justin M. Keyes" Date: Sat, 29 Jun 2019 16:39:22 +0200 Subject: [PATCH] viml/profile: switch to uv_gettimeofday() #10356 Performance of high-resolution time (clock_gettime via uv_hrtime) is expensive on some systems. For profiling VimL, syntax, etc., we don't care about nanosecond-precision and monotonicity edge-cases, so avoid uv_hrtime(). closes #10328 From the uv__hrtime() source: https://github.com/libuv/libuv/blob/0cdb4a5b4b706d0e09413d9270da28f9a88dc083/src/unix/linux-core.c#L442-L462 /* Prefer CLOCK_MONOTONIC_COARSE if available but only when it has * millisecond granularity or better. CLOCK_MONOTONIC_COARSE is * serviced entirely from the vDSO, whereas CLOCK_MONOTONIC may * decide to make a costly system call. */ This micro-benchmark (Debug build) shows negligible differences on my system: #include ... proftime_T tm = profile_start(); int trials = 999999; int64_t t = 0; struct timeval tv; for (int i = 0; i < trials; i++) { t += gettimeofday(&tv,NULL); } tm = profile_end(tm); ILOG("%d trials of gettimeofday: %s", trials, profile_msg(tm)); tm = profile_start(); for (int i = 0; i < trials; i++) { t += os_hrtime(); } tm = profile_end(tm); ILOG("%d trials of os_hrtime: %s", trials, profile_msg(tm)); tm = profile_start(); for (int i = 0; i < trials; i++) { t += os_utime(); } tm = profile_end(tm); ILOG("%d trials of os_utime: %s", trials, profile_msg(tm)); ILOG("%zu", t); --- src/nvim/assert.h | 7 ++-- src/nvim/eval.c | 2 +- src/nvim/os/time.c | 46 +++++++++++++++++++++++++-- src/nvim/profile.c | 79 ++++++++++++++++++++-------------------------- 4 files changed, 84 insertions(+), 50 deletions(-) diff --git a/src/nvim/assert.h b/src/nvim/assert.h index 34734f294d..1361879876 100644 --- a/src/nvim/assert.h +++ b/src/nvim/assert.h @@ -133,8 +133,10 @@ /// Alternative for compilers without __builtin_xx_overflow ? /// https://stackoverflow.com/a/44830670/152142 /// -/// @param MAX Maximum value of the narrowest type of operand. -/// Not used if compiler supports __builtin_add_overflow. +/// @param a Operand 1. +/// @param b Operand 2. +/// @param c Where to store the result. +/// @param t Result type. Not used if compiler supports __builtin_add_overflow. #ifdef HAVE_BUILTIN_ADD_OVERFLOW # define STRICT_ADD(a, b, c, t) \ do { \ @@ -150,6 +152,7 @@ /// @def STRICT_SUB /// @brief Subtracts (a - b) and stores result in `c`. Aborts on overflow. +/// @see STRICT_ADD #ifdef HAVE_BUILTIN_ADD_OVERFLOW # define STRICT_SUB(a, b, c, t) \ do { \ diff --git a/src/nvim/eval.c b/src/nvim/eval.c index ca2f4da22c..ddd2a06f4a 100644 --- a/src/nvim/eval.c +++ b/src/nvim/eval.c @@ -16536,7 +16536,7 @@ static void f_reltimefloat(typval_T *argvars , typval_T *rettv, FunPtr fptr) rettv->v_type = VAR_FLOAT; rettv->vval.v_float = 0; if (list2proftime(&argvars[0], &tm) == OK) { - rettv->vval.v_float = ((float_T)tm) / 1000000000; + rettv->vval.v_float = ((float_T)tm) / 1000000; } } diff --git a/src/nvim/os/time.c b/src/nvim/os/time.c index 31ef1a0cd6..18239c5566 100644 --- a/src/nvim/os/time.c +++ b/src/nvim/os/time.c @@ -9,6 +9,7 @@ #include +#include "nvim/assert.h" #include "nvim/os/time.h" #include "nvim/os/input.h" #include "nvim/event/loop.h" @@ -22,6 +23,7 @@ static uv_cond_t delay_cond; #ifdef INCLUDE_GENERATED_DECLARATIONS # include "os/time.c.generated.h" #endif + /// Initializes the time module void time_init(void) { @@ -29,15 +31,53 @@ void time_init(void) uv_cond_init(&delay_cond); } -/// Obtain a high-resolution timer value +/// Gets the current time with microsecond (μs) precision. /// -/// @return a timer value, not related to the time of day and not subject -/// to clock drift. The value is expressed in nanoseconds. +/// Subject to system-clock quirks (drift, going backwards, skipping). +/// But it is much faster than os_hrtime() on some systems. #10328 +/// +/// @see gettimeofday(2) +/// +/// @return Current time in microseconds. +uint64_t os_utime(void) + FUNC_ATTR_WARN_UNUSED_RESULT +{ + uv_timeval64_t tm; + int e = uv_gettimeofday(&tm); + if (e != 0 || tm.tv_sec < 0 || tm.tv_usec < 0) { + return 0; + } + uint64_t rv = (uint64_t)tm.tv_sec * 1000 * 1000; // s => μs + STRICT_ADD(rv, tm.tv_usec, &rv, uint64_t); + return rv; +} + +/// Gets a high-resolution (nanosecond), monotonically-increasing time relative +/// to an arbitrary time in the past. +/// +/// Not related to the time of day and therefore not subject to clock drift. +/// +/// @return Relative time value with nanosecond precision. uint64_t os_hrtime(void) + FUNC_ATTR_WARN_UNUSED_RESULT { return uv_hrtime(); } +/// Gets a millisecond-resolution, monotonically-increasing time relative to an +/// arbitrary time in the past. +/// +/// Not related to the time of day and therefore not subject to clock drift. +/// The value is cached by the loop, it will not change until the next +/// loop-tick (unless uv_update_time is called). +/// +/// @return Relative time value with millisecond precision. +uint64_t os_now(void) + FUNC_ATTR_WARN_UNUSED_RESULT +{ + return uv_now(&main_loop.uv); +} + /// Sleeps for `ms` milliseconds. /// /// @param ms Number of milliseconds to sleep diff --git a/src/nvim/profile.c b/src/nvim/profile.c index 8fb8e92add..cc12e00396 100644 --- a/src/nvim/profile.c +++ b/src/nvim/profile.c @@ -16,43 +16,38 @@ # include "profile.c.generated.h" #endif -/// functions for profiling - static proftime_T prof_wait_time; -/// profile_start - return the current time +/// Gets the current time. /// /// @return the current time proftime_T profile_start(void) FUNC_ATTR_WARN_UNUSED_RESULT { - return os_hrtime(); + return os_utime(); } -/// profile_end - compute the time elapsed +/// Computes the time elapsed. /// -/// @return the elapsed time from `tm` until now. +/// @return Elapsed time from `tm` until now. proftime_T profile_end(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT { - return os_hrtime() - tm; + return profile_sub(os_utime(), tm); } -/// profile_msg - return a string that represents the time in `tm` +/// Gets a string representing time `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". +/// @param tm Time +/// @return 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); - + snprintf(buf, sizeof(buf), "%10.6lf", (double)tm / 1000000.0); return buf; } -/// profile_setlimit - return the time `msec` into the future +/// Gets the time `msec` into the future. /// /// @param msec milliseconds, the maximum number of milliseconds is /// (2^63 / 10^6) - 1 = 9.223372e+12. @@ -64,14 +59,13 @@ proftime_T profile_setlimit(int64_t msec) FUNC_ATTR_WARN_UNUSED_RESULT // no limit return profile_zero(); } + assert(msec <= (INT64_MAX / 1000LL) - 1); - assert(msec <= (INT64_MAX / 1000000LL) - 1); - - proftime_T nsec = (proftime_T) msec * 1000000ULL; - return os_hrtime() + nsec; + proftime_T usec = (proftime_T)msec * 1000ULL; + return os_utime() + usec; } -/// profile_passed_limit - check if current time has passed `tm` +/// Checks 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. @@ -81,11 +75,10 @@ bool profile_passed_limit(proftime_T tm) FUNC_ATTR_WARN_UNUSED_RESULT // timer was not set return false; } - - return profile_cmp(os_hrtime(), tm) < 0; + return profile_cmp(os_utime(), tm) < 0; } -/// profile_zero - obtain the zero time +/// Gets the zero time. /// /// @return the zero time proftime_T profile_zero(void) FUNC_ATTR_CONST @@ -93,7 +86,7 @@ proftime_T profile_zero(void) FUNC_ATTR_CONST return 0; } -/// profile_divide - divide the time `tm` by `count`. +/// Divides time `tm` by `count`. /// /// @return 0 if count <= 0, otherwise tm / count proftime_T profile_divide(proftime_T tm, int count) FUNC_ATTR_CONST @@ -105,7 +98,7 @@ proftime_T profile_divide(proftime_T tm, int count) FUNC_ATTR_CONST return (proftime_T) round((double) tm / (double) count); } -/// profile_add - add the time `tm2` to `tm1` +/// Adds time `tm2` to `tm1`. /// /// @return `tm1` + `tm2` proftime_T profile_add(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST @@ -113,16 +106,15 @@ proftime_T profile_add(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST return tm1 + tm2; } -/// profile_sub - subtract `tm2` from `tm1` +/// Subtracts time `tm2` from `tm1`. /// /// @return `tm1` - `tm2` proftime_T profile_sub(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST { - return tm1 - tm2; + return tm1 > tm2 ? tm1 - tm2 : 0; // os_utime() may go backwards. } -/// profile_self - add the `self` time from the total time and the -/// children's time +/// Adds the `self` time from the total time and the `children` time. /// /// @return if `total` <= `children`, then self, otherwise `self` + `total` - /// `children` @@ -139,7 +131,7 @@ proftime_T profile_self(proftime_T self, proftime_T total, proftime_T children) return profile_sub(profile_add(self, total), children); } -/// profile_get_wait - get the current waittime +/// Gets the current waittime. /// /// @return the current waittime proftime_T profile_get_wait(void) FUNC_ATTR_PURE @@ -147,13 +139,13 @@ proftime_T profile_get_wait(void) FUNC_ATTR_PURE return prof_wait_time; } -/// profile_set_wait - set the current waittime +/// Sets the current waittime. void profile_set_wait(proftime_T wait) { prof_wait_time = wait; } -/// profile_sub_wait - subtract the passed waittime since `tm` +/// Subtracts the passed waittime since `tm`. /// /// @return `tma` - (waittime - `tm`) proftime_T profile_sub_wait(proftime_T tm, proftime_T tma) FUNC_ATTR_PURE @@ -162,7 +154,7 @@ proftime_T profile_sub_wait(proftime_T tm, proftime_T tma) FUNC_ATTR_PURE return profile_sub(tma, tm3); } -/// profile_equal - check if `tm1` is equal to `tm2` +/// Checks if time `tm1` is equal to `tm2`. /// /// @return true if `tm1` == `tm2` bool profile_equal(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST @@ -170,7 +162,7 @@ bool profile_equal(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST return tm1 == tm2; } -/// sgn64 - calculates the sign of a 64-bit integer +/// Calculates the sign of a 64-bit integer. /// /// @return -1, 0, or +1 static inline int sgn64(int64_t x) FUNC_ATTR_CONST @@ -178,10 +170,9 @@ static inline int sgn64(int64_t x) FUNC_ATTR_CONST return (int) ((x > 0) - (x < 0)); } -/// profile_cmp - compare profiling times +/// Compares profiling times. /// -/// Only guarantees correct results if both input times are not more than -/// 150 years apart. +/// Times `tm1` and `tm2` must be less 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 @@ -193,7 +184,7 @@ int profile_cmp(proftime_T tm1, proftime_T tm2) FUNC_ATTR_CONST static proftime_T g_start_time; static proftime_T g_prev_time; -/// time_push - save the previous time before doing something that could nest +/// Saves the previous time before doing something that could nest. /// /// After calling this function, the static global `g_prev_time` will /// contain the current time. @@ -212,7 +203,7 @@ void time_push(proftime_T *rel, proftime_T *start) g_prev_time = now; } -/// time_pop - compute the prev time after doing something that could nest +/// Computes the prev time after doing something that could nest. /// /// Subtracts `tp` from the static global `g_prev_time`. /// @@ -222,18 +213,18 @@ void time_pop(proftime_T tp) g_prev_time -= tp; } -/// time_diff - print the difference between `then` and `now` +/// Prints the difference between `then` and `now`. /// /// the format is "msec.usec". static void time_diff(proftime_T then, proftime_T now) { proftime_T diff = profile_sub(now, then); - fprintf(time_fd, "%07.3lf", (double) diff / 1.0E6); + fprintf(time_fd, "%07.3lf", (double)diff / 1.0E3); } -/// time_start - initialize the startuptime code +/// Initializes the startuptime code. /// -/// Needs to be called once before calling other startuptime code (such as +/// Must be called once before calling other startuptime code (such as /// time_{push,pop,msg,...}). /// /// @param message the message that will be displayed @@ -253,7 +244,7 @@ void time_start(const char *message) time_msg(message, NULL); } -/// time_msg - print out timing info +/// Prints out timing info. /// /// @warning don't forget to call `time_start()` once before calling this. ///