rrl WIP: increase precision of cpu work estimate using RDTSC

diff --git a/daemon/rrl/api.h b/daemon/rrl/api.h
index c0aa1c16a84a5172f876a65196c58f6bc12a320b..72c690b4440a3179ea46a69ffc2912424bf6cd3d 100644 (file)
--- a/daemon/rrl/api.h
+++ b/daemon/rrl/api.h
@@ -21,17 +21,32 @@ void kr_rrl_deinit(void);
 
 // TODO: reconsider `static inline` cases below
 
+#define USE_RDTSC  // TODO: determine somehow, probably on runtime
+#ifdef USE_RDTSC
+#include "x86intrin.h"
+#endif
+
+typedef struct {
+       uint64_t ns; /// monotonic nanoseconds, probably won't wrap
+#ifdef USE_RDTSC
+       uint64_t ticks; // TSC ticks, may be desynchronized on different cpus
+#endif
+} kr_rrl_stamp_t;
 
 typedef struct {
        bool do_sample; /// whether to sample; could be important if _COARSE isn't available
        int8_t is_accounting; /// whether currently accounting the time to someone; should be 0/1
        union kr_sockaddr addr; /// request source (to which we account) or AF_UNSPEC if unknown yet
-       uint64_t stamp; /// monotonic nanoseconds, probably won't wrap
+       kr_rrl_stamp_t stamp; /// timestamp when accounting started
+#ifdef USE_RDTSC
+       kr_rrl_stamp_t total; /// sum of all accounted timediffs
+       uint64_t ns_res; // resolution of ns stamp
+#endif
 } kr_rrl_sample_state_t;
 extern kr_rrl_sample_state_t kr_rrl_sample_state;
 
 #include <time.h>
-static inline uint64_t get_stamp(void)
+static inline void get_stamp(kr_rrl_stamp_t *stamp)
 {
        /* TODO:
            * think of strategies for non-Linux
@@ -48,10 +63,37 @@ static inline uint64_t get_stamp(void)
 
        struct timespec now_ts = {0};
        clock_gettime(CLOCK_MONOTONIC_COARSE, &now_ts);
-       return now_ts.tv_nsec + 1000*1000*1000 * (uint64_t)now_ts.tv_sec;
+
        /* Note: kr_now() call would be similarly cheap and typically more precise,
         * but it gets updated exactly in moments when we don't want,
         * so the _COARSE stamp is be much better in this case. */
+       stamp->ns = now_ts.tv_nsec + 1000*1000*1000 * (uint64_t)now_ts.tv_sec;
+#ifdef USE_RDTSC
+       stamp->ticks = _rdtsc();
+#endif
+}
+static inline uint64_t get_stamp_diff_ns(kr_rrl_stamp_t *stamp_end, kr_rrl_stamp_t *stamp_begin) {
+       uint64_t ns = stamp_end->ns - stamp_begin->ns;
+#ifdef USE_RDTSC
+       if (stamp_end->ticks <= stamp_begin->ticks) {
+               return ns;
+       }
+       uint64_t ticks = stamp_end->ticks - stamp_begin->ticks;
+       kr_rrl_sample_state.total.ns += ns;
+       kr_rrl_sample_state.total.ticks += ticks;
+       uint64_t ticks_ns = ticks * ((double)kr_rrl_sample_state.total.ns / kr_rrl_sample_state.total.ticks);
+
+       if (kr_rrl_sample_state.ns_res == 0) {
+               struct timespec res = {0};
+               clock_getres(CLOCK_MONOTONIC_COARSE, &res);
+               kr_rrl_sample_state.ns_res = res.tv_nsec;
+               kr_log_notice(DEVEL, "%5.3f ms res\n", kr_rrl_sample_state.ns_res / 1000000.0); // TODO drop
+       }
+       if ((ns + kr_rrl_sample_state.ns_res >= ticks_ns) && (ticks_ns + kr_rrl_sample_state.ns_res >= ns)) {
+               return ticks_ns;
+       }
+#endif
+       return ns;
 }
 
 /// Start accounting work, if not doing it already.
@@ -60,7 +102,7 @@ static inline void kr_rrl_sample_start(void)
        if (!kr_rrl_sample_state.do_sample) return;
        kr_assert(!kr_rrl_sample_state.is_accounting);
        ++kr_rrl_sample_state.is_accounting;
-       kr_rrl_sample_state.stamp = get_stamp();
+       get_stamp(&kr_rrl_sample_state.stamp);
        kr_rrl_sample_state.addr.ip.sa_family = AF_UNSPEC;
 }
 
@@ -97,12 +139,15 @@ static inline void kr_rrl_sample_stop(void)
        if (kr_fails_assert(kr_rrl_sample_state.is_accounting > 0)) return; // weird
        if (--kr_rrl_sample_state.is_accounting) return;
 
-       const uint64_t elapsed = get_stamp() - kr_rrl_sample_state.stamp;
-       if (!elapsed) return;
+       kr_rrl_stamp_t stamp;
+       get_stamp(&stamp);
+       const uint64_t elapsed = get_stamp_diff_ns(&stamp, &kr_rrl_sample_state.stamp);
+       const uint64_t elapsed_coarse = stamp.ns - kr_rrl_sample_state.stamp.ns;  // TODO drop
+       if ((elapsed < 1000) && !elapsed_coarse) return;
 
        // we accounted something
        // FIXME: drop the log, add KRU, etc.
-       kr_log_notice(DEVEL, "%5.1f ms for %s\n", elapsed / 1000000.0,
+       kr_log_notice(DEVEL, "%5.3f ms (%5.3f ms _COARSE) for %s\n", elapsed / 1000000.0, elapsed_coarse / 1000000.0,
                        kr_straddr(&kr_rrl_sample_state.addr.ip));
        // TODO: some queries of internal origin have suspicioiusly high numbers.
        // We won't be really accounting those, but it might suggest some other issue.