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:
0cdb4a5b4b/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 <sys/time.h>
    ...

    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

@@ -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.
+/// @param a  Operand 1.
-///            Not used if compiler supports __builtin_add_overflow.
+/// @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 { \

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;
   }
 }
 

src/nvim/os/time.c

@@ -9,6 +9,7 @@
 
 #include <uv.h>
 
+#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
+/// Subject to system-clock quirks (drift, going backwards, skipping).
-///         to clock drift. The value is expressed in nanoseconds.
+/// 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

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
+/// @param tm Time
-/// @return a static string representing `tm` in the
+/// @return Static string representing `tm` in the form "seconds.microseconds".
-///         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 / 1000000.0);
-  snprintf(buf, sizeof(buf), "%10.6lf", (double)tm / 1000000000.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 usec = (proftime_T)msec * 1000ULL;
-
+  return os_utime() + usec;
-  proftime_T nsec = (proftime_T) msec * 1000000ULL;
-  return os_hrtime() + nsec;
 }
 
-/// 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_utime(), tm) < 0;
-  return profile_cmp(os_hrtime(), 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
+/// Adds the `self` time from the total time and the `children` time.
-///                children's 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
+/// Times `tm1` and `tm2` must be less than 150 years apart.
-/// 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.
 ///